[TC-MF-1.13] Open commissioning window on DUT twice using ECM then BCM [DUT - Commissionee] ***************** 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 17785187439892091247 12344321 ***************** Step 2 ***************** TH_CR1 opens a commissioning window on DUT_CE using ECM and TH_CR3 Commissions with DUT_CE open-commissioning-window 12344321 -t 100 -o 1 -d 3840 -i 1000 setup-payload parse-manual 35564377374 connect -ip 192.168.1.111 126769499 43214321 zclread Basic VendorName 43214321 0 0 chip-device-ctrl > open-commissioning-window 12344321 -t 100 -o 1 -d 3840 -i 1000 [1634582431.606904][24228:24235] CHIP:CTL: OpenCommissioningWindow for device ID 12344321 [1634582431.612053][24228:24235] CHIP:DMG: ICR moving to [Initialize] [1634582431.612118][24228:24235] CHIP:DMG: ICR moving to [AddCommand] [1634582431.612301][24228:24235] CHIP:IN: Secure message was encrypted: Msg ID 2 [1634582431.612337][24228:24235] CHIP:IN: Build encrypted message 0x119f5cf8 to 0x0000000000BC5C01 of type 8 and protocolId 1 on exchange 20432r with MessageCounter 2. [1634582431.612381][24228:24235] CHIP:IN: Sending encrypted msg 0x119f5cf8 to 0x0000000000BC5C01 at utc time: 2417894 msec [1634582431.612410][24228:24235] CHIP:IN: Sending msg on generic transport [1634582431.612547][24228:24235] CHIP:DMG: ICR moving to [ Sending] [1634582431.612608][24228:24235] CHIP:CTL: Manual pairing code: [35564377374] [1634582431.612694][24228:24235] CHIP:CTL: SetupQRCode: [MT:000006DB0065HN5UP20] [1634582432.392689][24228:24235] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 20432i [1634582432.392870][24228:24235] CHIP:EM: Rxd Ack; Removing MessageCounter:00000002 from Retrans Table [1634582432.392936][24228:24235] CHIP:EM: Removed CHIP MessageCounter:00000002 from RetransTable [1634582432.393062][24228:24235] CHIP:DMG: InvokeCommand = [1634582432.393134][24228:24235] CHIP:DMG: { [1634582432.393189][24228:24235] CHIP:DMG: CommandList = [1634582432.393257][24228:24235] CHIP:DMG: [ [1634582432.393321][24228:24235] CHIP:DMG: CommandDataElement = [1634582432.393407][24228:24235] CHIP:DMG: { [1634582432.393515][24228:24235] CHIP:DMG: CommandPath = [1634582432.393600][24228:24235] CHIP:DMG: { [1634582432.393683][24228:24235] CHIP:DMG: EndpointId = 0x0, [1634582432.393776][24228:24235] CHIP:DMG: ClusterId = 0x3c, [1634582432.393861][24228:24235] CHIP:DMG: CommandId = 0x0, [1634582432.393933][24228:24235] CHIP:DMG: }, [1634582432.394023][24228:24235] CHIP:DMG: [1634582432.394094][24228:24235] CHIP:DMG: StatusElement = [1634582432.394166][24228:24235] CHIP:DMG: { [1634582432.394245][24228:24235] CHIP:DMG: GeneralCode = 0x0, [1634582432.394330][24228:24235] CHIP:DMG: ProtocolId = 0x1, [1634582432.394419][24228:24235] CHIP:DMG: protocolCode = 0x0, [1634582432.394505][24228:24235] CHIP:DMG: }, [1634582432.394588][24228:24235] CHIP:DMG: [1634582432.394652][24228:24235] CHIP:DMG: }, [1634582432.394731][24228:24235] CHIP:DMG: [1634582432.394792][24228:24235] CHIP:DMG: ], [1634582432.394867][24228:24235] CHIP:DMG: [1634582432.394924][24228:24235] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582432.395604][24228:24235] CHIP:ZCL: DefaultResponse: [1634582432.395667][24228:24235] CHIP:ZCL: Transaction: 0xffffb3dc4240 [1634582432.395722][24228:24235] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582432.395787][24228:24235] CHIP:CTL: Successfully opened pairing window on the device [1634582432.395934][24228:24235] CHIP:DMG: ICR moving to [Uninitiali] [1634582432.396015][24228:24235] CHIP:EM: Sending Standalone Ack for MessageCounter:00000002 [1634582432.396191][24228:24235] CHIP:IN: Secure message was encrypted: Msg ID 3 [1634582432.396257][24228:24235] CHIP:IN: Build encrypted message 0xffffa3ffdad0 to 0x0000000000BC5C01 of type 16 and protocolId 0 on exchange 20432r with MessageCounter 3. [1634582432.396345][24228:24235] CHIP:IN: Sending encrypted msg 0xffffa3ffdad0 to 0x0000000000BC5C01 at utc time: 2418678 msec [1634582432.396408][24228:24235] CHIP:IN: Sending msg on generic transport [1634582432.396629][24228:24235] CHIP:EM: Flushed pending ack for MessageCounter:00000002 chip-device-ctrl > setup-payload parse-manual 35564377374 Version: 0 VendorID: 0 ProductID: 0 CommissioningFlow: 0 RendezvousInformation: 0 Discriminator: 3840 SetUpPINCode: 126769499 chip-device-ctrl > connect -ip 192.168.1.111 126769499 43214321 Device is assigned with nodeid = 43214321 [1634582452103] [16891:802149] CHIP: [SC] Assigned local session key ID 1 [1634582452103] [16891:802149] CHIP: [IN] Build plaintext message 0x7fd4bc8bc058 to 0x0000000000000000 of type 32 and protocolId 0 on exchange 30718r with MessageCounter 2696887695. [1634582452103] [16891:802149] CHIP: [IN] Sending plaintext msg 0x7fd4bc8bc058 to 0x0000000000000000 at utc time: 234897793 msec [1634582452103] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582452104] [16891:802149] CHIP: [SC] Sent PBKDF param request [1634582452104] [16891:802149] CHIP: [CTL] SyncSetKeyValue on StartKeyID [1634582453944] [16891:802149] CHIP: [EM] Received message of type 0x21 with vendorId 0x0000 and protocolId 0x0000 on exchange 30718i [1634582453944] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:A0BF3D8F from Retrans Table [1634582453944] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:A0BF3D8F from RetransTable [1634582453944] [16891:802149] CHIP: [SC] Received PBKDF param response [1634582453944] [16891:802149] CHIP: [SC] Peer assigned session ID 2 [1634582453948] [16891:802149] CHIP: [EM] Piggybacking Ack for MessageCounter:2CA5702C on exchange: 30718i [1634582453948] [16891:802149] CHIP: [IN] Build plaintext message 0x7fd4bc8bc058 to 0x0000000000000000 of type 34 and protocolId 0 on exchange 30718r with MessageCounter 2696887696. [1634582453948] [16891:802149] CHIP: [IN] Sending plaintext msg 0x7fd4bc8bc058 to 0x0000000000000000 at utc time: 234899637 msec [1634582453948] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582453948] [16891:802149] CHIP: [SC] Sent spake2p msg1 [1634582456399] [16891:802149] CHIP: [EM] Received message of type 0x23 with vendorId 0x0000 and protocolId 0x0000 on exchange 30718i [1634582456399] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:A0BF3D90 from Retrans Table [1634582456399] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:A0BF3D90 from RetransTable [1634582456399] [16891:802149] CHIP: [SC] Received spake2p msg2 [1634582456400] [16891:802149] CHIP: [EM] Piggybacking Ack for MessageCounter:2CA5702D on exchange: 30718i [1634582456400] [16891:802149] CHIP: [IN] Build plaintext message 0x7fd4bc8bc058 to 0x0000000000000000 of type 36 and protocolId 0 on exchange 30718r with MessageCounter 2696887697. [1634582456400] [16891:802149] CHIP: [IN] Sending plaintext msg 0x7fd4bc8bc058 to 0x0000000000000000 at utc time: 234902089 msec [1634582456400] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582456400] [16891:802149] CHIP: [SC] Sent spake2p msg3 [1634582457362] [16891:802149] CHIP: [EM] Received message of type 0x40 with vendorId 0x0000 and protocolId 0x0000 on exchange 30718i [1634582457362] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:A0BF3D91 from Retrans Table [1634582457362] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:A0BF3D91 from RetransTable [1634582457363] [16891:802149] CHIP: [IN] New secure session created for device 0x00000000029365F1, key 2!! [1634582457363] [16891:802149] CHIP: [CTL] Remote device completed SPAKE2+ handshake [1634582457363] [16891:802149] CHIP: [CTL] Arming failsafe [1634582457363] [16891:802149] CHIP: [DMG] ICR moving to [Initialize] [1634582457363] [16891:802149] CHIP: [DMG] ICR moving to [AddCommand] [1634582457363] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 0 [1634582457363] [16891:802149] CHIP: [IN] Build encrypted message 0x7fd4bc8bc058 to 0x00000000029365F1 of type 8 and protocolId 1 on exchange 30719r with MessageCounter 0. [1634582457363] [16891:802149] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 234903053 msec [1634582457363] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582457363] [16891:802149] CHIP: [DMG] ICR moving to [ Sending] [1634582457363] [16891:802149] CHIP: [EM] Sending Standalone Ack for MessageCounter:2CA5702E [1634582457363] [16891:802149] CHIP: [IN] Build plaintext message 0x70000f291560 to 0x0000000000000000 of type 16 and protocolId 0 on exchange 30718r with MessageCounter 2696887698. [1634582457363] [16891:802149] CHIP: [IN] Sending plaintext msg 0x70000f291560 to 0x0000000000000000 at utc time: 234903053 msec [1634582457363] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582457363] [16891:802149] CHIP: [EM] Flushed pending ack for MessageCounter:2CA5702E [1634582457940] [16891:803304] CHIP: [EM] Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 30719i [1634582457941] [16891:803304] CHIP: [EM] Rxd Ack; Removing MessageCounter:00000000 from Retrans Table [1634582457941] [16891:803304] CHIP: [EM] Removed CHIP MessageCounter:00000000 from RetransTable [1634582457941] [16891:803304] CHIP: [DMG] InvokeCommand = [1634582457941] [16891:803304] CHIP: [DMG] { [1634582457941] [16891:803304] CHIP: [DMG] CommandList = [1634582457941] [16891:803304] CHIP: [DMG] [ [1634582457941] [16891:803304] CHIP: [DMG] CommandDataElement = [1634582457941] [16891:803304] CHIP: [DMG] { [1634582457941] [16891:803304] CHIP: [DMG] CommandPath = [1634582457941] [16891:803304] CHIP: [DMG] { [1634582457941] [16891:803304] CHIP: [DMG] EndpointId = 0x0, [1634582457941] [16891:803304] CHIP: [DMG] ClusterId = 0x30, [1634582457941] [16891:803304] CHIP: [DMG] CommandId = 0x0, [1634582457941] [16891:803304] CHIP: [DMG] }, [1634582457941] [16891:803304] CHIP: [DMG] [1634582457941] [16891:803304] CHIP: [DMG] StatusElement = [1634582457941] [16891:803304] CHIP: [DMG] { [1634582457941] [16891:803304] CHIP: [DMG] GeneralCode = 0x0, [1634582457941] [16891:803304] CHIP: [DMG] ProtocolId = 0x1, [1634582457941] [16891:803304] CHIP: [DMG] protocolCode = 0x0, [1634582457941] [16891:803304] CHIP: [DMG] }, [1634582457941] [16891:803304] CHIP: [DMG] [1634582457941] [16891:803304] CHIP: [DMG] }, [1634582457941] [16891:803304] CHIP: [DMG] [1634582457941] [16891:803304] CHIP: [DMG] ], [1634582457941] [16891:803304] CHIP: [DMG] [1634582457941] [16891:803304] CHIP: [DMG] } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582457941] [16891:803304] CHIP: [ZCL] DefaultResponse: [1634582457941] [16891:803304] CHIP: [ZCL] Transaction: 0x10e614a60 [1634582457941] [16891:803304] CHIP: [ZCL] status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582457941] [16891:803304] CHIP: [CTL] Received success response 0xcf78 [1634582457941] [16891:803304] CHIP: [CTL] Setting Regulatory Config [1634582457941] [16891:803304] CHIP: [CTL] Unable to find regulatory location, defaulting to outdoor [1634582457941] [16891:803304] CHIP: [CTL] Unable to find country code, defaulting to WW [1634582457941] [16891:803304] CHIP: [DMG] ICR moving to [Initialize] [1634582457941] [16891:803304] CHIP: [DMG] ICR moving to [AddCommand] [1634582457942] [16891:803304] CHIP: [IN] Secure message was encrypted: Msg ID 1 [1634582457942] [16891:803304] CHIP: [IN] Build encrypted message 0x7fd4bc8bc058 to 0x00000000029365F1 of type 8 and protocolId 1 on exchange 30720r with MessageCounter 1. [1634582457942] [16891:803304] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 234903631 msec [1634582457942] [16891:803304] CHIP: [IN] Sending msg on generic transport [1634582457942] [16891:803304] CHIP: [DMG] ICR moving to [ Sending] [1634582457942] [16891:803304] CHIP: [DMG] ICR moving to [Uninitiali] [1634582457942] [16891:803304] CHIP: [EM] Sending Standalone Ack for MessageCounter:00000001 [1634582457942] [16891:803304] CHIP: [IN] Secure message was encrypted: Msg ID 2 [1634582457942] [16891:803304] CHIP: [IN] Build encrypted message 0x70000f49d400 to 0x00000000029365F1 of type 16 and protocolId 0 on exchange 30719r with MessageCounter 2. [1634582457942] [16891:803304] CHIP: [IN] Sending encrypted msg 0x70000f49d400 to 0x00000000029365F1 at utc time: 234903631 msec [1634582457942] [16891:803304] CHIP: [IN] Sending msg on generic transport [1634582457942] [16891:803304] CHIP: [EM] Flushed pending ack for MessageCounter:00000001 [1634582458757] [16891:802149] CHIP: [EM] Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 30720i [1634582458757] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:00000001 from Retrans Table [1634582458757] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:00000001 from RetransTable [1634582458758] [16891:802149] CHIP: [DMG] InvokeCommand = [1634582458758] [16891:802149] CHIP: [DMG] { [1634582458758] [16891:802149] CHIP: [DMG] CommandList = [1634582458758] [16891:802149] CHIP: [DMG] [ [1634582458758] [16891:802149] CHIP: [DMG] CommandDataElement = [1634582458758] [16891:802149] CHIP: [DMG] { [1634582458758] [16891:802149] CHIP: [DMG] CommandPath = [1634582458758] [16891:802149] CHIP: [DMG] { [1634582458758] [16891:802149] CHIP: [DMG] EndpointId = 0x0, [1634582458758] [16891:802149] CHIP: [DMG] ClusterId = 0x30, [1634582458758] [16891:802149] CHIP: [DMG] CommandId = 0x2, [1634582458758] [16891:802149] CHIP: [DMG] }, [1634582458758] [16891:802149] CHIP: [DMG] [1634582458758] [16891:802149] CHIP: [DMG] StatusElement = [1634582458758] [16891:802149] CHIP: [DMG] { [1634582458758] [16891:802149] CHIP: [DMG] GeneralCode = 0x0, [1634582458758] [16891:802149] CHIP: [DMG] ProtocolId = 0x1, [1634582458758] [16891:802149] CHIP: [DMG] protocolCode = 0x0, [1634582458758] [16891:802149] CHIP: [DMG] }, [1634582458758] [16891:802149] CHIP: [DMG] [1634582458758] [16891:802149] CHIP: [DMG] }, [1634582458758] [16891:802149] CHIP: [DMG] [1634582458758] [16891:802149] CHIP: [DMG] ], [1634582458758] [16891:802149] CHIP: [DMG] [1634582458758] [16891:802149] CHIP: [DMG] } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582458758] [16891:802149] CHIP: [ZCL] DefaultResponse: [1634582458758] [16891:802149] CHIP: [ZCL] Transaction: 0x10e614bc0 [1634582458758] [16891:802149] CHIP: [ZCL] status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582458758] [16891:802149] CHIP: [CTL] Received success response 0xf78 [1634582458758] [16891:802149] CHIP: [CTL] Exchanging certificates [1634582458758] [16891:802149] CHIP: [CTL] Sending OpCSR request to 0x7fd4bde6a030 device [1634582458758] [16891:802149] CHIP: [DMG] ICR moving to [Initialize] [1634582458758] [16891:802149] CHIP: [DMG] ICR moving to [AddCommand] [1634582458758] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 3 [1634582458758] [16891:802149] CHIP: [IN] Build encrypted message 0x7fd4bc8bc058 to 0x00000000029365F1 of type 8 and protocolId 1 on exchange 30721r with MessageCounter 3. [1634582458758] [16891:802149] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 234904448 msec [1634582458758] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582458759] [16891:802149] CHIP: [DMG] ICR moving to [ Sending] [1634582458759] [16891:802149] CHIP: [CTL] Sent OpCSR request, waiting for the CSR [1634582458759] [16891:802149] CHIP: [DMG] ICR moving to [Uninitiali] [1634582458759] [16891:802149] CHIP: [EM] Sending Standalone Ack for MessageCounter:00000002 [1634582458759] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 4 [1634582458759] [16891:802149] CHIP: [IN] Build encrypted message 0x70000f291400 to 0x00000000029365F1 of type 16 and protocolId 0 on exchange 30720r with MessageCounter 4. [1634582458759] [16891:802149] CHIP: [IN] Sending encrypted msg 0x70000f291400 to 0x00000000029365F1 at utc time: 234904448 msec [1634582458759] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582458759] [16891:802149] CHIP: [EM] Flushed pending ack for MessageCounter:00000002 [1634582459797] [16891:803304] CHIP: [EM] Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 30721i [1634582459797] [16891:803304] CHIP: [EM] Rxd Ack; Removing MessageCounter:00000003 from Retrans Table [1634582459797] [16891:803304] CHIP: [EM] Removed CHIP MessageCounter:00000003 from RetransTable [1634582459797] [16891:803304] CHIP: [DMG] InvokeCommand = [1634582459797] [16891:803304] CHIP: [DMG] { [1634582459797] [16891:803304] CHIP: [DMG] CommandList = [1634582459797] [16891:803304] CHIP: [DMG] [ [1634582459797] [16891:803304] CHIP: [DMG] CommandDataElement = [1634582459797] [16891:803304] CHIP: [DMG] { [1634582459797] [16891:803304] CHIP: [DMG] CommandPath = [1634582459797] [16891:803304] CHIP: [DMG] { [1634582459797] [16891:803304] CHIP: [DMG] EndpointId = 0x0, [1634582459797] [16891:803304] CHIP: [DMG] ClusterId = 0x3e, [1634582459797] [16891:803304] CHIP: [DMG] CommandId = 0x5, [1634582459797] [16891:803304] CHIP: [DMG] }, [1634582459797] [16891:803304] CHIP: [DMG] [1634582459797] [16891:803304] CHIP: [DMG] CommandData = [1634582459797] [16891:803304] CHIP: [DMG] { [1634582459797] [16891:803304] CHIP: [DMG] 0x0 = [ [1634582459797] [16891:803304] CHIP: [DMG] 0x15, 0x30, 0x1, 0xce, 0x30, 0x81, 0xcb, 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, [1634582459797] [16891:803304] CHIP: [DMG] ] [1634582459797] [16891:803304] CHIP: [DMG] 0x1 = [ [1634582459797] [16891:803304] CHIP: [DMG] [1634582459797] [16891:803304] CHIP: [DMG] ] [1634582459797] [16891:803304] CHIP: [DMG] }, [1634582459797] [16891:803304] CHIP: [DMG] }, [1634582459797] [16891:803304] CHIP: [DMG] [1634582459797] [16891:803304] CHIP: [DMG] ], [1634582459797] [16891:803304] CHIP: [DMG] [1634582459797] [16891:803304] CHIP: [DMG] } [1634582459797] [16891:803304] CHIP: [ZCL] Received Cluster Command: Cluster=3e Command=5 Endpoint=0 [1634582459798] [16891:803304] CHIP: [ZCL] OpCSRResponse: [1634582459798] [16891:803304] CHIP: [ZCL] NOCSRElements: 255 [1634582459798] [16891:803304] CHIP: [ZCL] AttestationSignature: 0 [1634582459798] [16891:803304] CHIP: [CTL] Received certificate signing request from the device [1634582459798] [16891:803304] CHIP: [CTL] Getting certificate chain for the device from the issuer [1634582459798] [16891:803304] CHIP: [CTL] Verifying Certificate Signing Request [1634582459798] [16891:803304] CHIP: [CTL] Generating NOC [1634582459799] [16891:803304] CHIP: [CTL] Generating ICAC [1634582459799] [16891:803304] CHIP: [CTL] Providing certificate chain to the commissioner [1634582459799] [16891:803304] CHIP: [CTL] Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:183: Success [1634582459799] [16891:803304] CHIP: [CTL] Sending root certificate to the device [1634582459799] [16891:803304] CHIP: [DMG] ICR moving to [Initialize] [1634582459799] [16891:803304] CHIP: [DMG] ICR moving to [AddCommand] [1634582459799] [16891:803304] CHIP: [IN] Secure message was encrypted: Msg ID 5 [1634582459799] [16891:803304] CHIP: [IN] Build encrypted message 0x7fd4bc8bc058 to 0x00000000029365F1 of type 8 and protocolId 1 on exchange 30722r with MessageCounter 5. [1634582459799] [16891:803304] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 234905489 msec [1634582459799] [16891:803304] CHIP: [IN] Sending msg on generic transport [1634582459799] [16891:803304] CHIP: [DMG] ICR moving to [ Sending] [1634582459799] [16891:803304] CHIP: [CTL] Sent root certificate to the device [1634582459800] [16891:803304] CHIP: [DMG] ICR moving to [Uninitiali] [1634582459800] [16891:803304] CHIP: [EM] Sending Standalone Ack for MessageCounter:00000003 [1634582459800] [16891:803304] CHIP: [IN] Secure message was encrypted: Msg ID 6 [1634582459800] [16891:803304] CHIP: [IN] Build encrypted message 0x70000f49d400 to 0x00000000029365F1 of type 16 and protocolId 0 on exchange 30721r with MessageCounter 6. [1634582459800] [16891:803304] CHIP: [IN] Sending encrypted msg 0x70000f49d400 to 0x00000000029365F1 at utc time: 234905489 msec [1634582459800] [16891:803304] CHIP: [IN] Sending msg on generic transport [1634582459800] [16891:803304] CHIP: [EM] Flushed pending ack for MessageCounter:00000003 [1634582461317] [16891:803304] CHIP: [EM] Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 30722i [1634582461318] [16891:803304] CHIP: [EM] Rxd Ack; Removing MessageCounter:00000005 from Retrans Table [1634582461318] [16891:803304] CHIP: [EM] Removed CHIP MessageCounter:00000005 from RetransTable [1634582461318] [16891:803304] CHIP: [DMG] InvokeCommand = [1634582461318] [16891:803304] CHIP: [DMG] { [1634582461318] [16891:803304] CHIP: [DMG] CommandList = [1634582461318] [16891:803304] CHIP: [DMG] [ [1634582461318] [16891:803304] CHIP: [DMG] CommandDataElement = [1634582461318] [16891:803304] CHIP: [DMG] { [1634582461318] [16891:803304] CHIP: [DMG] CommandPath = [1634582461318] [16891:803304] CHIP: [DMG] { [1634582461318] [16891:803304] CHIP: [DMG] EndpointId = 0x0, [1634582461318] [16891:803304] CHIP: [DMG] ClusterId = 0x3e, [1634582461318] [16891:803304] CHIP: [DMG] CommandId = 0xb, [1634582461318] [16891:803304] CHIP: [DMG] }, [1634582461318] [16891:803304] CHIP: [DMG] [1634582461318] [16891:803304] CHIP: [DMG] StatusElement = [1634582461318] [16891:803304] CHIP: [DMG] { [1634582461318] [16891:803304] CHIP: [DMG] GeneralCode = 0x0, [1634582461318] [16891:803304] CHIP: [DMG] ProtocolId = 0x1, [1634582461318] [16891:803304] CHIP: [DMG] protocolCode = 0x0, [1634582461318] [16891:803304] CHIP: [DMG] }, [1634582461318] [16891:803304] CHIP: [DMG] [1634582461318] [16891:803304] CHIP: [DMG] }, [1634582461318] [16891:803304] CHIP: [DMG] [1634582461318] [16891:803304] CHIP: [DMG] ], [1634582461318] [16891:803304] CHIP: [DMG] [1634582461318] [16891:803304] CHIP: [DMG] } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582461319] [16891:803304] CHIP: [ZCL] DefaultResponse: [1634582461319] [16891:803304] CHIP: [ZCL] Transaction: 0x10e614bc0 [1634582461319] [16891:803304] CHIP: [ZCL] status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582461319] [16891:803304] CHIP: [CTL] Device confirmed that it has received the root certificate [1634582461319] [16891:803304] CHIP: [CTL] Sending operational certificate chain to the device [1634582461319] [16891:803304] CHIP: [DMG] ICR moving to [Initialize] [1634582461319] [16891:803304] CHIP: [DMG] ICR moving to [AddCommand] [1634582461319] [16891:803304] CHIP: [IN] Secure message was encrypted: Msg ID 7 [1634582461319] [16891:803304] CHIP: [IN] Build encrypted message 0x7fd4bc8bc058 to 0x00000000029365F1 of type 8 and protocolId 1 on exchange 30723r with MessageCounter 7. [1634582461319] [16891:803304] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 234907008 msec [1634582461319] [16891:803304] CHIP: [IN] Sending msg on generic transport [1634582461319] [16891:803304] CHIP: [DMG] ICR moving to [ Sending] [1634582461319] [16891:803304] CHIP: [CTL] Sent operational certificate to the device [1634582461319] [16891:803304] CHIP: [DMG] ICR moving to [Uninitiali] [1634582461319] [16891:803304] CHIP: [EM] Sending Standalone Ack for MessageCounter:00000004 [1634582461319] [16891:803304] CHIP: [IN] Secure message was encrypted: Msg ID 8 [1634582461319] [16891:803304] CHIP: [IN] Build encrypted message 0x70000f49d400 to 0x00000000029365F1 of type 16 and protocolId 0 on exchange 30722r with MessageCounter 8. [1634582461319] [16891:803304] CHIP: [IN] Sending encrypted msg 0x70000f49d400 to 0x00000000029365F1 at utc time: 234907008 msec [1634582461319] [16891:803304] CHIP: [IN] Sending msg on generic transport [1634582461319] [16891:803304] CHIP: [EM] Flushed pending ack for MessageCounter:00000004 [1634582464202] [16891:802149] CHIP: [EM] Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 30723i [1634582464202] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:00000007 from Retrans Table [1634582464202] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:00000007 from RetransTable [1634582464202] [16891:802149] CHIP: [DMG] InvokeCommand = [1634582464202] [16891:802149] CHIP: [DMG] { [1634582464202] [16891:802149] CHIP: [DMG] CommandList = [1634582464202] [16891:802149] CHIP: [DMG] [ [1634582464202] [16891:802149] CHIP: [DMG] CommandDataElement = [1634582464202] [16891:802149] CHIP: [DMG] { [1634582464202] [16891:802149] CHIP: [DMG] CommandPath = [1634582464202] [16891:802149] CHIP: [DMG] { [1634582464202] [16891:802149] CHIP: [DMG] EndpointId = 0x0, [1634582464202] [16891:802149] CHIP: [DMG] ClusterId = 0x3e, [1634582464202] [16891:802149] CHIP: [DMG] CommandId = 0x8, [1634582464202] [16891:802149] CHIP: [DMG] }, [1634582464202] [16891:802149] CHIP: [DMG] [1634582464202] [16891:802149] CHIP: [DMG] CommandData = [1634582464202] [16891:802149] CHIP: [DMG] { [1634582464202] [16891:802149] CHIP: [DMG] 0x0 = 0, [1634582464202] [16891:802149] CHIP: [DMG] 0x1 = 2, [1634582464202] [16891:802149] CHIP: [DMG] 0x2 = [ [1634582464202] [16891:802149] CHIP: [DMG] [1634582464202] [16891:802149] CHIP: [DMG] ] [1634582464202] [16891:802149] CHIP: [DMG] }, [1634582464202] [16891:802149] CHIP: [DMG] }, [1634582464202] [16891:802149] CHIP: [DMG] [1634582464202] [16891:802149] CHIP: [DMG] ], [1634582464202] [16891:802149] CHIP: [DMG] [1634582464202] [16891:802149] CHIP: [DMG] } [1634582464202] [16891:802149] CHIP: [ZCL] Received Cluster Command: Cluster=3e Command=8 Endpoint=0 [1634582464203] [16891:802149] CHIP: [ZCL] NOCResponse: [1634582464203] [16891:802149] CHIP: [ZCL] StatusCode: 0 [1634582464203] [16891:802149] CHIP: [ZCL] FabricIndex: 2 [1634582464203] [16891:802149] CHIP: [ZCL] DebugText: 0 [1634582464203] [16891:802149] CHIP: [CTL] Device returned status 0 on receiving the NOC [1634582464203] [16891:802149] CHIP: [CTL] Operational credentials provisioned on device 0x7fd4bde6a030 [1634582464203] [16891:802149] CHIP: [CTL] Enabling Network [1634582464203] [16891:802149] CHIP: [DMG] ICR moving to [Initialize] [1634582464203] [16891:802149] CHIP: [DMG] ICR moving to [AddCommand] [1634582464203] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 9 [1634582464203] [16891:802149] CHIP: [IN] Build encrypted message 0x7fd4bc8bc058 to 0x00000000029365F1 of type 8 and protocolId 1 on exchange 30724r with MessageCounter 9. [1634582464203] [16891:802149] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 234909892 msec [1634582464203] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582464203] [16891:802149] CHIP: [DMG] ICR moving to [ Sending] [1634582464203] [16891:802149] CHIP: [DMG] ICR moving to [Uninitiali] [1634582464203] [16891:802149] CHIP: [EM] Sending Standalone Ack for MessageCounter:00000005 [1634582464203] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 10 [1634582464203] [16891:802149] CHIP: [IN] Build encrypted message 0x70000f291400 to 0x00000000029365F1 of type 16 and protocolId 0 on exchange 30723r with MessageCounter 10. [1634582464203] [16891:802149] CHIP: [IN] Sending encrypted msg 0x70000f291400 to 0x00000000029365F1 at utc time: 234909893 msec [1634582464203] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582464203] [16891:802149] CHIP: [EM] Flushed pending ack for MessageCounter:00000005 [1634582465310] [16891:802149] CHIP: [EM] Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 30724i [1634582465310] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:00000009 from Retrans Table [1634582465310] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:00000009 from RetransTable [1634582465310] [16891:802149] CHIP: [DMG] InvokeCommand = [1634582465310] [16891:802149] CHIP: [DMG] { [1634582465310] [16891:802149] CHIP: [DMG] CommandList = [1634582465310] [16891:802149] CHIP: [DMG] [ [1634582465310] [16891:802149] CHIP: [DMG] CommandDataElement = [1634582465310] [16891:802149] CHIP: [DMG] { [1634582465310] [16891:802149] CHIP: [DMG] CommandPath = [1634582465310] [16891:802149] CHIP: [DMG] { [1634582465310] [16891:802149] CHIP: [DMG] EndpointId = 0x0, [1634582465310] [16891:802149] CHIP: [DMG] ClusterId = 0x31, [1634582465310] [16891:802149] CHIP: [DMG] CommandId = 0xc, [1634582465310] [16891:802149] CHIP: [DMG] }, [1634582465310] [16891:802149] CHIP: [DMG] [1634582465310] [16891:802149] CHIP: [DMG] StatusElement = [1634582465310] [16891:802149] CHIP: [DMG] { [1634582465310] [16891:802149] CHIP: [DMG] GeneralCode = 0x0, [1634582465310] [16891:802149] CHIP: [DMG] ProtocolId = 0x1, [1634582465310] [16891:802149] CHIP: [DMG] protocolCode = 0x0, [1634582465310] [16891:802149] CHIP: [DMG] }, [1634582465310] [16891:802149] CHIP: [DMG] [1634582465310] [16891:802149] CHIP: [DMG] }, [1634582465310] [16891:802149] CHIP: [DMG] [1634582465310] [16891:802149] CHIP: [DMG] ], [1634582465310] [16891:802149] CHIP: [DMG] [1634582465310] [16891:802149] CHIP: [DMG] } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582465311] [16891:802149] CHIP: [ZCL] DefaultResponse: [1634582465311] [16891:802149] CHIP: [ZCL] Transaction: 0x10e614bc0 [1634582465311] [16891:802149] CHIP: [ZCL] status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582465311] [16891:802149] CHIP: [CTL] Received success response 0xf78 [1634582465311] [16891:802149] CHIP: [CTL] Finding node on operational network [1634582465311] [16891:802149] CHIP: [DMG] ICR moving to [Uninitiali] [1634582465311] [16891:802149] CHIP: [EM] Sending Standalone Ack for MessageCounter:00000006 [1634582465311] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 11 [1634582465311] [16891:802149] CHIP: [IN] Build encrypted message 0x70000f291400 to 0x00000000029365F1 of type 16 and protocolId 0 on exchange 30724r with MessageCounter 11. [1634582465311] [16891:802149] CHIP: [IN] Sending encrypted msg 0x70000f291400 to 0x00000000029365F1 at utc time: 234911001 msec [1634582465311] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582465311] [16891:802149] CHIP: [EM] Flushed pending ack for MessageCounter:00000006 [1634582465312] [16891:802149] CHIP: [DL] Resolved interface id: 4 [1634582465313] [16891:802149] CHIP: [DL] Mdns: OnGetAddrInfo hostname:A402A0A44DD4.local. [1634582465313] [16891:802149] CHIP: [DIS] Node ID resolved for 0x00000000029365F1 to [fe80::d64d:a4ff:fea0:2a4]:5540 [1634582465313] [16891:802149] CHIP: [CTL] SyncSetKeyValue on PairedDevice29365f1 Node address has been updated [1634582465313] [16891:802149] CHIP: [CTL] OperationalDiscoveryComplete for device ID 43214321 [1634582465313] [16891:802149] CHIP: [CTL] Enabling CASE session establishment for the device [1634582465313] [16891:802149] CHIP: [CTL] SyncSetKeyValue on PairedDevice29365f1 [1634582465313] [16891:802149] CHIP: [IN] Marking old secure session for device 0x00000000029365F1 as expired [1634582465314] [16891:802149] CHIP: [CTL] SyncSetKeyValue on PairedDevice29365f1 [1634582465314] [16891:802149] CHIP: [CTL] SyncSetKeyValue on StartKeyID [1634582465314] [16891:802149] CHIP: [IN] Build plaintext message 0x7fd4bc8bc058 to 0x0000000000000000 of type 48 and protocolId 0 on exchange 30725r with MessageCounter 2974256741. [1634582465314] [16891:802149] CHIP: [IN] Sending plaintext msg 0x7fd4bc8bc058 to 0x0000000000000000 at utc time: 234911004 msec [1634582465314] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582465314] [16891:802149] CHIP: [SC] Sent SigmaR1 msg [1634582468997] [16891:802149] CHIP: [EM] Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 30725i [1634582468997] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:B1478E65 from Retrans Table [1634582468997] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:B1478E65 from RetransTable [1634582468997] [16891:802149] CHIP: [SC] Received SigmaR2 msg [1634582468997] [16891:802149] CHIP: [SC] Peer assigned session key ID 4 [1634582468999] [16891:802149] CHIP: [SC] Sending SigmaR3 [1634582468999] [16891:802149] CHIP: [EM] Piggybacking Ack for MessageCounter:B1155FAF on exchange: 30725i [1634582468999] [16891:802149] CHIP: [IN] Build plaintext message 0x7fd4bc8bc058 to 0x0000000000000000 of type 50 and protocolId 0 on exchange 30725r with MessageCounter 2974256742. [1634582468999] [16891:802149] CHIP: [IN] Sending plaintext msg 0x7fd4bc8bc058 to 0x0000000000000000 at utc time: 234914689 msec [1634582468999] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582468999] [16891:802149] CHIP: [SC] Sent SigmaR3 msg [1634582468999] [16891:802149] CHIP: [IN] New secure session created for device 0x00000000029365F1, key 4!! [1634582468999] [16891:802149] CHIP: [CTL] Calling commissioning complete [1634582468999] [16891:802149] CHIP: [DMG] ICR moving to [Initialize] [1634582469000] [16891:802149] CHIP: [DMG] ICR moving to [AddCommand] [1634582469000] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 0 [1634582469000] [16891:802149] CHIP: [IN] Build encrypted message 0x7fd4bc8bc070 to 0x00000000029365F1 of type 8 and protocolId 1 on exchange 30726r with MessageCounter 0. [1634582469000] [16891:802149] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc070 to 0x00000000029365F1 at utc time: 234914689 msec [1634582469000] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582469000] [16891:802149] CHIP: [DMG] ICR moving to [ Sending] [1634582471761] [16891:802149] CHIP: [EM] Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 30725i [1634582471761] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:B1478E66 from Retrans Table [1634582471761] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:B1478E66 from RetransTable [1634582471761] [16891:802149] CHIP: [EM] Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 30726i [1634582471761] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:00000000 from Retrans Table [1634582471761] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:00000000 from RetransTable [1634582471761] [16891:802149] CHIP: [DMG] InvokeCommand = [1634582471762] [16891:802149] CHIP: [DMG] { [1634582471762] [16891:802149] CHIP: [DMG] CommandList = [1634582471762] [16891:802149] CHIP: [DMG] [ [1634582471762] [16891:802149] CHIP: [DMG] CommandDataElement = [1634582471762] [16891:802149] CHIP: [DMG] { [1634582471762] [16891:802149] CHIP: [DMG] CommandPath = [1634582471762] [16891:802149] CHIP: [DMG] { [1634582471762] [16891:802149] CHIP: [DMG] EndpointId = 0x0, [1634582471762] [16891:802149] CHIP: [DMG] ClusterId = 0x30, [1634582471762] [16891:802149] CHIP: [DMG] CommandId = 0x4, [1634582471762] [16891:802149] CHIP: [DMG] }, [1634582471762] [16891:802149] CHIP: [DMG] [1634582471762] [16891:802149] CHIP: [DMG] StatusElement = [1634582471762] [16891:802149] CHIP: [DMG] { [1634582471762] [16891:802149] CHIP: [DMG] GeneralCode = 0x0, [1634582471762] [16891:802149] CHIP: [DMG] ProtocolId = 0x1, [1634582471762] [16891:802149] CHIP: [DMG] protocolCode = 0x0, [1634582471762] [16891:802149] CHIP: [DMG] }, [1634582471762] [16891:802149] CHIP: [DMG] [1634582471762] [16891:802149] CHIP: [DMG] }, [1634582471762] [16891:802149] CHIP: [DMG] [1634582471762] [16891:802149] CHIP: [DMG] ], [1634582471762] [16891:802149] CHIP: [DMG] [1634582471762] [16891:802149] CHIP: [DMG] } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582471762] [16891:802149] CHIP: [ZCL] DefaultResponse: [1634582471762] [16891:802149] CHIP: [ZCL] Transaction: 0x10e614a60 [1634582471762] [16891:802149] CHIP: [ZCL] status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582471762] [16891:802149] CHIP: [CTL] Received success response 0xf78 [1634582471762] [16891:802149] CHIP: [CTL] Rendezvous cleanup [1634582471762] [16891:802149] CHIP: [CTL] SyncSetKeyValue on PairedDevice29365f1 [1634582471762] [16891:802149] CHIP: [CTL] SyncSetKeyValue on ListPairedDevices0 [1634582471762] [16891:802149] CHIP: [CTL] SyncSetKeyValue on StartKeyID [1634582471762] [16891:802149] CHIP: [CTL] SyncSetKeyValue on PairedDevice29365f1 Secure Session to Device Established [1634582471763] [16891:802149] CHIP: [DMG] ICR moving to [Uninitiali] [1634582471763] [16891:802149] CHIP: [EM] Sending Standalone Ack for MessageCounter:00000001 [1634582471763] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 1 Device temporary node id (**this does not match spec**): 43214321 [1634582471763] [16891:802149] CHIP: [IN] Build encrypted message 0x70000f291400 to 0x00000000029365F1 of type 16 and protocolId 0 on exchange 30726r with MessageCounter 1. [1634582471763] [16891:802149] CHIP: [IN] Sending encrypted msg 0x70000f291400 to 0x00000000029365F1 at utc time: 234917452 msec [1634582471763] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582471763] [16891:802149] CHIP: [EM] Flushed pending ack for MessageCounter:00000001 chip-device-ctrl > chip-device-ctrl > chip-device-ctrl > chip-device-ctrl > zclread Basic VendorName 43214321 0 0 [1634582474323] [16891:802149] CHIP: [IN] Build plaintext message 0x7fd4bc8bc058 to 0x0000000000000000 of type 48 and protocolId 0 on exchange 30727r with MessageCounter 2974256743. [1634582474323] [16891:802149] CHIP: [IN] Sending plaintext msg 0x7fd4bc8bc058 to 0x0000000000000000 at utc time: 234920012 msec [1634582474323] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582474323] [16891:802149] CHIP: [SC] Sent SigmaR1 msg [1634582474323] [16891:802149] CHIP: [DMG] SendReadRequest: Client[0] [ INIT] [1634582474323] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 2 [1634582474323] [16891:802149] CHIP: [IN] Build encrypted message 0x7fd4bc8bc070 to 0x00000000029365F1 of type 2 and protocolId 1 on exchange 30728r with MessageCounter 2. [1634582474323] [16891:802149] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc070 to 0x00000000029365F1 at utc time: 234920013 msec [1634582474323] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582474324] [16891:802149] CHIP: [DMG] Client[0] moving to [AwaitingInitialReport] [1634582476685] [16891:802149] CHIP: [EM] Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 30727i [1634582476685] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:B1478E67 from Retrans Table [1634582476685] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:B1478E67 from RetransTable [1634582476685] [16891:802149] CHIP: [SC] Received SigmaR2 msg [1634582476685] [16891:802149] CHIP: [SC] Peer assigned session key ID 5 [1634582476687] [16891:802149] CHIP: [SC] Sending SigmaR3 [1634582476687] [16891:802149] CHIP: [EM] Piggybacking Ack for MessageCounter:B1155FB1 on exchange: 30727i [1634582476687] [16891:802149] CHIP: [IN] Build plaintext message 0x7fd4bc8bc058 to 0x0000000000000000 of type 50 and protocolId 0 on exchange 30727r with MessageCounter 2974256744. [1634582476687] [16891:802149] CHIP: [IN] Sending plaintext msg 0x7fd4bc8bc058 to 0x0000000000000000 at utc time: 234922377 msec [1634582476687] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582476688] [16891:802149] CHIP: [SC] Sent SigmaR3 msg [1634582476688] [16891:802149] CHIP: [IN] New secure session created for device 0x00000000029365F1, key 5!! [1634582476688] [16891:802149] CHIP: [EM] Received message of type 0x05 with vendorId 0x0000 and protocolId 0x0001 on exchange 30728i [1634582476688] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:00000002 from Retrans Table [1634582476688] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:00000002 from RetransTable [1634582476688] [16891:802149] CHIP: [DMG] ReportData = [1634582476688] [16891:802149] CHIP: [DMG] { [1634582476688] [16891:802149] CHIP: [DMG] AttributeDataList = [1634582476688] [16891:802149] CHIP: [DMG] [ [1634582476688] [16891:802149] CHIP: [DMG] AttributeDataElement = [1634582476688] [16891:802149] CHIP: [DMG] { [1634582476688] [16891:802149] CHIP: [DMG] AttributePath = [1634582476688] [16891:802149] CHIP: [DMG] { [1634582476688] [16891:802149] CHIP: [DMG] NodeId = 0x29365f1, [1634582476688] [16891:802149] CHIP: [DMG] EndpointId = 0x0, [1634582476688] [16891:802149] CHIP: [DMG] ClusterId = 0x28, [1634582476688] [16891:802149] CHIP: [DMG] FieldTag = 0x1, [1634582476688] [16891:802149] CHIP: [DMG] } [1634582476688] [16891:802149] CHIP: [DMG] [1634582476688] [16891:802149] CHIP: [DMG] Data = "TEST_VENDOR", [1634582476688] [16891:802149] CHIP: [DMG] DataElementVersion = 0x0, [1634582476688] [16891:802149] CHIP: [DMG] }, [1634582476688] [16891:802149] CHIP: [DMG] [1634582476688] [16891:802149] CHIP: [DMG] ], [1634582476688] [16891:802149] CHIP: [DMG] [1634582476688] [16891:802149] CHIP: [DMG] } [1634582476689] [16891:802149] CHIP: [ZCL] ReadAttributesResponse: [1634582476689] [16891:802149] CHIP: [ZCL] ClusterId: 0x0000_0028 [1634582476689] [16891:802149] CHIP: [ZCL] attributeId: 0x0000_0001 [1634582476689] [16891:802149] CHIP: [ZCL] status: Success (0x0000) [1634582476689] [16891:802149] CHIP: [ZCL] attribute TLV Type: 0x0c [1634582476689] [16891:802149] CHIP: [ZCL] attributeValue: (span of length 11) 84 69 83 84 95 86 69 78 68 79 82 [1634582476689] [16891:802149] CHIP: [EM] Piggybacking Ack for MessageCounter:00000002 on exchange: 30728i [1634582476689] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 3 [1634582476689] [16891:802149] CHIP: [IN] Build encrypted message 0x7fd4bc8bc070 to 0x00000000029365F1 of type 1 and protocolId 1 on exchange 30728r with MessageCounter 3. AttributeReadResult(path=AttributePath(nodeId=43214321, endpointId=0, clusterId=40, attributeId=1), status=0, value='TEST_VENDOR') [1634582476689] [16891:802149] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc070 to 0x00000000029365F1 at utc time: 234922378 msec [1634582476689] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582476689] [16891:802149] CHIP: [DMG] Client[0] moving to [UNINIT] chip-device-ctrl > zclread Basic VendorName 43214321 0 0 [1634582479814] [16891:802149] CHIP: [DMG] SendReadRequest: Client[0] [ INIT] [1634582479814] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 0 [1634582479814] [16891:802149] CHIP: [IN] Build encrypted message 0x7fd4bc8bc058 to 0x00000000029365F1 of type 2 and protocolId 1 on exchange 30729r with MessageCounter 0. [1634582479814] [16891:802149] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 234925503 msec [1634582479814] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582479814] [16891:802149] CHIP: [DMG] Client[0] moving to [AwaitingInitialReport] [1634582480676] [16891:802149] CHIP: [EM] Received message of type 0x05 with vendorId 0x0000 and protocolId 0x0001 on exchange 30729i [1634582480676] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:00000000 from Retrans Table [1634582480676] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:00000000 from RetransTable [1634582480676] [16891:802149] CHIP: [DMG] ReportData = [1634582480676] [16891:802149] CHIP: [DMG] { [1634582480676] [16891:802149] CHIP: [DMG] AttributeDataList = [1634582480676] [16891:802149] CHIP: [DMG] [ [1634582480676] [16891:802149] CHIP: [DMG] AttributeDataElement = [1634582480676] [16891:802149] CHIP: [DMG] { [1634582480676] [16891:802149] CHIP: [DMG] AttributePath = [1634582480676] [16891:802149] CHIP: [DMG] { [1634582480676] [16891:802149] CHIP: [DMG] NodeId = 0x29365f1, [1634582480676] [16891:802149] CHIP: [DMG] EndpointId = 0x0, [1634582480676] [16891:802149] CHIP: [DMG] ClusterId = 0x28, [1634582480676] [16891:802149] CHIP: [DMG] FieldTag = 0x1, [1634582480676] [16891:802149] CHIP: [DMG] } [1634582480676] [16891:802149] CHIP: [DMG] [1634582480676] [16891:802149] CHIP: [DMG] Data = "TEST_VENDOR", [1634582480676] [16891:802149] CHIP: [DMG] DataElementVersion = 0x0, [1634582480676] [16891:802149] CHIP: [DMG] }, [1634582480676] [16891:802149] CHIP: [DMG] [1634582480676] [16891:802149] CHIP: [DMG] ], [1634582480676] [16891:802149] CHIP: [DMG] [1634582480676] [16891:802149] CHIP: [DMG] } [1634582480676] [16891:802149] CHIP: [ZCL] ReadAttributesResponse: [1634582480676] [16891:802149] CHIP: [ZCL] ClusterId: 0x0000_0028 [1634582480676] [16891:802149] CHIP: [ZCL] attributeId: 0x0000_0001 [1634582480677] [16891:802149] CHIP: [ZCL] status: Success (0x0000) [1634582480677] [16891:802149] CHIP: [ZCL] attribute TLV Type: 0x0c [1634582480677] [16891:802149] CHIP: [ZCL] attributeValue: (span of length 11) 84 69 83 84 95 86 69 78 68 79 82 [1634582480677] [16891:802149] CHIP: [EM] Piggybacking Ack for MessageCounter:00000001 on exchange: 30729i [1634582480677] [16891:802149] CHIP: [IN] Secure message was encrypted: Msg ID 1 [1634582480677] [16891:802149] CHIP: [IN] Build encrypted message 0x7fd4bc8bc058 to 0x00000000029365F1 of type 1 and protocolId 1 on exchange 30729r with MessageCounter 1. [1634582480677] [16891:802149] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 234926366 msec AttributeReadResult(path=AttributePath(nodeId=43214321, endpointId=0, clusterId=40, attributeId=1), status=0, value='TEST_VENDOR') [1634582480677] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582480677] [16891:802149] CHIP: [DMG] Client[0] moving to [UNINIT] chip-device-ctrl > [1634582481285] [16891:802149] CHIP: [EM] Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 30729i [1634582481286] [16891:802149] CHIP: [EM] Rxd Ack; Removing MessageCounter:00000001 from Retrans Table [1634582481286] [16891:802149] CHIP: [EM] Removed CHIP MessageCounter:00000001 from RetransTable ***************** Step 3 ***************** TH_CR1 opens a commissioning window on DUT_CE using ECM and TH_CR2 Commissions with DUT_CE open-commissioning-window 12344321 -t 100 -o 1 -d 3840 -i 1000 setup-payload parse-manual 36032026164 connect -ip 192.168.1.111 42871712 12345678 zclread Basic VendorName 12345678 0 0 chip-device-ctrl > open-commissioning-window 12344321 -t 100 -o 1 -d 3840 -i 1000 [1634582502.797925][24228:24235] CHIP:CTL: OpenCommissioningWindow for device ID 12344321 [1634582502.806748][24228:24235] CHIP:DMG: ICR moving to [Initialize] [1634582502.806815][24228:24235] CHIP:DMG: ICR moving to [AddCommand] [1634582502.807001][24228:24235] CHIP:IN: Secure message was encrypted: Msg ID 4 [1634582502.807042][24228:24235] CHIP:IN: Build encrypted message 0x119f5cf8 to 0x0000000000BC5C01 of type 8 and protocolId 1 on exchange 20433r with MessageCounter 4. [1634582502.807089][24228:24235] CHIP:IN: Sending encrypted msg 0x119f5cf8 to 0x0000000000BC5C01 at utc time: 2489089 msec [1634582502.807121][24228:24235] CHIP:IN: Sending msg on generic transport [1634582502.807270][24228:24235] CHIP:DMG: ICR moving to [ Sending] [1634582502.807336][24228:24235] CHIP:CTL: Manual pairing code: [36032026164] [1634582502.807425][24228:24235] CHIP:CTL: SetupQRCode: [MT:000006DB00S68S2GY00] chip-device-ctrl > [1634582503.682307][24228:24235] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 20433i [1634582503.682475][24228:24235] CHIP:EM: Rxd Ack; Removing MessageCounter:00000004 from Retrans Table [1634582503.682533][24228:24235] CHIP:EM: Removed CHIP MessageCounter:00000004 from RetransTable [1634582503.682654][24228:24235] CHIP:DMG: InvokeCommand = [1634582503.682717][24228:24235] CHIP:DMG: { [1634582503.682765][24228:24235] CHIP:DMG: CommandList = [1634582503.682824][24228:24235] CHIP:DMG: [ [1634582503.682878][24228:24235] CHIP:DMG: CommandDataElement = [1634582503.682942][24228:24235] CHIP:DMG: { [1634582503.683001][24228:24235] CHIP:DMG: CommandPath = [1634582503.683116][24228:24235] CHIP:DMG: { [1634582503.683196][24228:24235] CHIP:DMG: EndpointId = 0x0, [1634582503.683282][24228:24235] CHIP:DMG: ClusterId = 0x3c, [1634582503.683364][24228:24235] CHIP:DMG: CommandId = 0x0, [1634582503.683442][24228:24235] CHIP:DMG: }, [1634582503.683522][24228:24235] CHIP:DMG: [1634582503.683584][24228:24235] CHIP:DMG: StatusElement = [1634582503.683653][24228:24235] CHIP:DMG: { [1634582503.683725][24228:24235] CHIP:DMG: GeneralCode = 0x0, [1634582503.683808][24228:24235] CHIP:DMG: ProtocolId = 0x1, [1634582503.683890][24228:24235] CHIP:DMG: protocolCode = 0x0, [1634582503.683967][24228:24235] CHIP:DMG: }, [1634582503.684038][24228:24235] CHIP:DMG: [1634582503.684094][24228:24235] CHIP:DMG: }, [1634582503.684163][24228:24235] CHIP:DMG: [1634582503.684216][24228:24235] CHIP:DMG: ], [1634582503.684282][24228:24235] CHIP:DMG: [1634582503.684331][24228:24235] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582503.684958][24228:24235] CHIP:ZCL: DefaultResponse: [1634582503.685015][24228:24235] CHIP:ZCL: Transaction: 0xffffb3dc4240 [1634582503.685062][24228:24235] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582503.685119][24228:24235] CHIP:CTL: Successfully opened pairing window on the device [1634582503.685263][24228:24235] CHIP:DMG: ICR moving to [Uninitiali] [1634582503.685344][24228:24235] CHIP:EM: Sending Standalone Ack for MessageCounter:00000003 [1634582503.685571][24228:24235] CHIP:IN: Secure message was encrypted: Msg ID 5 [1634582503.685641][24228:24235] CHIP:IN: Build encrypted message 0xffffa3ffdad0 to 0x0000000000BC5C01 of type 16 and protocolId 0 on exchange 20433r with MessageCounter 5. [1634582503.685726][24228:24235] CHIP:IN: Sending encrypted msg 0xffffa3ffdad0 to 0x0000000000BC5C01 at utc time: 2489968 msec [1634582503.685799][24228:24235] CHIP:IN: Sending msg on generic transport [1634582503.685994][24228:24235] CHIP:EM: Flushed pending ack for MessageCounter:00000003 chip-device-ctrl > setup-payload parse-manual 36032026164 Version: 0 VendorID: 0 ProductID: 0 CommissioningFlow: 0 RendezvousInformation: 0 Discriminator: 3840 SetUpPINCode: 42871712 chip-device-ctrl > connect -ip 192.168.1.111 42871712 12345678 Device is assigned with nodeid = 12345678 [1634582525.607279][21063:21070] CHIP:SC: Assigned local session key ID 1 [1634582525.607561][21063:21070] CHIP:IN: Build plaintext message 0x388dacf8 to 0x0000000000000000 of type 32 and protocolId 0 on exchange 28799r with MessageCounter 1445407237. [1634582525.607664][21063:21070] CHIP:IN: Sending plaintext msg 0x388dacf8 to 0x0000000000000000 at utc time: 2209778 msec [1634582525.607727][21063:21070] CHIP:IN: Sending msg on generic transport [1634582525.608002][21063:21070] CHIP:SC: Sent PBKDF param request [1634582525.608102][21063:21070] CHIP:CTL: SyncSetKeyValue on StartKeyID [1634582526.247505][21063:21070] CHIP:EM: Received message of type 0x21 with vendorId 0x0000 and protocolId 0x0000 on exchange 28799i [1634582526.247672][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:56272A05 from Retrans Table [1634582526.247736][21063:21070] CHIP:EM: Removed CHIP MessageCounter:56272A05 from RetransTable [1634582526.247829][21063:21070] CHIP:SC: Received PBKDF param response [1634582526.247942][21063:21070] CHIP:SC: Peer assigned session ID 6 [1634582526.258651][21063:21070] CHIP:EM: Piggybacking Ack for MessageCounter:D5A8C038 on exchange: 28799i [1634582526.258874][21063:21070] CHIP:IN: Build plaintext message 0x388dacf8 to 0x0000000000000000 of type 34 and protocolId 0 on exchange 28799r with MessageCounter 1445407238. [1634582526.258947][21063:21070] CHIP:IN: Sending plaintext msg 0x388dacf8 to 0x0000000000000000 at utc time: 2210430 msec [1634582526.258995][21063:21070] CHIP:IN: Sending msg on generic transport [1634582526.259177][21063:21070] CHIP:SC: Sent spake2p msg1 [1634582528.084693][21063:21070] CHIP:EM: Received message of type 0x23 with vendorId 0x0000 and protocolId 0x0000 on exchange 28799i [1634582528.084877][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:56272A06 from Retrans Table [1634582528.084926][21063:21070] CHIP:EM: Removed CHIP MessageCounter:56272A06 from RetransTable [1634582528.084998][21063:21070] CHIP:SC: Received spake2p msg2 [1634582528.087282][21063:21070] CHIP:EM: Piggybacking Ack for MessageCounter:D5A8C039 on exchange: 28799i [1634582528.087367][21063:21070] CHIP:IN: Build plaintext message 0x388dacf8 to 0x0000000000000000 of type 36 and protocolId 0 on exchange 28799r with MessageCounter 1445407239. [1634582528.087435][21063:21070] CHIP:IN: Sending plaintext msg 0x388dacf8 to 0x0000000000000000 at utc time: 2212258 msec [1634582528.087482][21063:21070] CHIP:IN: Sending msg on generic transport [1634582528.087651][21063:21070] CHIP:SC: Sent spake2p msg3 [1634582528.144541][21063:21070] CHIP:EM: Received message of type 0x40 with vendorId 0x0000 and protocolId 0x0000 on exchange 28799i [1634582528.144667][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:56272A07 from Retrans Table [1634582528.144706][21063:21070] CHIP:EM: Removed CHIP MessageCounter:56272A07 from RetransTable [1634582528.144838][21063:21070] CHIP:IN: New secure session created for device 0x0000000000BC614E, key 6!! [1634582528.144965][21063:21070] CHIP:CTL: Remote device completed SPAKE2+ handshake [1634582528.145006][21063:21070] CHIP:CTL: Arming failsafe [1634582528.145108][21063:21070] CHIP:DMG: ICR moving to [Initialize] [1634582528.145167][21063:21070] CHIP:DMG: ICR moving to [AddCommand] [1634582528.145334][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 0 [1634582528.145382][21063:21070] CHIP:IN: Build encrypted message 0x388dacf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 28800r with MessageCounter 0. [1634582528.145434][21063:21070] CHIP:IN: Sending encrypted msg 0x388dacf8 to 0x0000000000BC614E at utc time: 2212316 msec [1634582528.145471][21063:21070] CHIP:IN: Sending msg on generic transport [1634582528.145610][21063:21070] CHIP:DMG: ICR moving to [ Sending] [1634582528.145666][21063:21070] CHIP:EM: Sending Standalone Ack for MessageCounter:D5A8C03A [1634582528.145726][21063:21070] CHIP:IN: Build plaintext message 0xffffb17adb10 to 0x0000000000000000 of type 16 and protocolId 0 on exchange 28799r with MessageCounter 1445407240. [1634582528.145781][21063:21070] CHIP:IN: Sending plaintext msg 0xffffb17adb10 to 0x0000000000000000 at utc time: 2212317 msec [1634582528.145818][21063:21070] CHIP:IN: Sending msg on generic transport [1634582528.145921][21063:21070] CHIP:EM: Flushed pending ack for MessageCounter:D5A8C03A [1634582528.222667][21063:21070] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 28800i [1634582528.222798][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:00000000 from Retrans Table [1634582528.222845][21063:21070] CHIP:EM: Removed CHIP MessageCounter:00000000 from RetransTable [1634582528.222940][21063:21070] CHIP:DMG: InvokeCommand = [1634582528.222993][21063:21070] CHIP:DMG: { [1634582528.223034][21063:21070] CHIP:DMG: CommandList = [1634582528.223083][21063:21070] CHIP:DMG: [ [1634582528.223129][21063:21070] CHIP:DMG: CommandDataElement = [1634582528.223194][21063:21070] CHIP:DMG: { [1634582528.223244][21063:21070] CHIP:DMG: CommandPath = [1634582528.223303][21063:21070] CHIP:DMG: { [1634582528.223363][21063:21070] CHIP:DMG: EndpointId = 0x0, [1634582528.223432][21063:21070] CHIP:DMG: ClusterId = 0x30, [1634582528.223501][21063:21070] CHIP:DMG: CommandId = 0x0, [1634582528.223560][21063:21070] CHIP:DMG: }, [1634582528.223626][21063:21070] CHIP:DMG: [1634582528.223678][21063:21070] CHIP:DMG: StatusElement = [1634582528.223743][21063:21070] CHIP:DMG: { [1634582528.223807][21063:21070] CHIP:DMG: GeneralCode = 0x0, [1634582528.223875][21063:21070] CHIP:DMG: ProtocolId = 0x1, [1634582528.223942][21063:21070] CHIP:DMG: protocolCode = 0x0, [1634582528.224002][21063:21070] CHIP:DMG: }, [1634582528.224062][21063:21070] CHIP:DMG: [1634582528.224113][21063:21070] CHIP:DMG: }, [1634582528.224175][21063:21070] CHIP:DMG: [1634582528.224219][21063:21070] CHIP:DMG: ], [1634582528.224275][21063:21070] CHIP:DMG: [1634582528.224316][21063:21070] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582528.224978][21063:21070] CHIP:ZCL: DefaultResponse: [1634582528.225030][21063:21070] CHIP:ZCL: Transaction: 0xffffb93a1240 [1634582528.225071][21063:21070] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582528.225121][21063:21070] CHIP:CTL: Received success response 0xb814 [1634582528.225183][21063:21070] CHIP:CTL: Setting Regulatory Config [1634582528.225250][21063:21070] CHIP:CTL: Unable to find regulatory location, defaulting to outdoor [1634582528.225301][21063:21070] CHIP:CTL: Unable to find country code, defaulting to WW [1634582528.225387][21063:21070] CHIP:DMG: ICR moving to [Initialize] [1634582528.225461][21063:21070] CHIP:DMG: ICR moving to [AddCommand] [1634582528.225658][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 1 [1634582528.225712][21063:21070] CHIP:IN: Build encrypted message 0x388dacf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 28801r with MessageCounter 1. [1634582528.225775][21063:21070] CHIP:IN: Sending encrypted msg 0x388dacf8 to 0x0000000000BC614E at utc time: 2212397 msec [1634582528.225822][21063:21070] CHIP:IN: Sending msg on generic transport [1634582528.225988][21063:21070] CHIP:DMG: ICR moving to [ Sending] [1634582528.226140][21063:21070] CHIP:DMG: ICR moving to [Uninitiali] [1634582528.226196][21063:21070] CHIP:EM: Sending Standalone Ack for MessageCounter:00000001 [1634582528.226294][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 2 [1634582528.226343][21063:21070] CHIP:IN: Build encrypted message 0xffffb17adad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 28800r with MessageCounter 2. [1634582528.226401][21063:21070] CHIP:IN: Sending encrypted msg 0xffffb17adad0 to 0x0000000000BC614E at utc time: 2212397 msec [1634582528.226447][21063:21070] CHIP:IN: Sending msg on generic transport [1634582528.226569][21063:21070] CHIP:EM: Flushed pending ack for MessageCounter:00000001 [1634582528.318196][21063:21070] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 28801i [1634582528.318342][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:00000001 from Retrans Table [1634582528.318394][21063:21070] CHIP:EM: Removed CHIP MessageCounter:00000001 from RetransTable [1634582528.318500][21063:21070] CHIP:DMG: InvokeCommand = [1634582528.318560][21063:21070] CHIP:DMG: { [1634582528.318607][21063:21070] CHIP:DMG: CommandList = [1634582528.318663][21063:21070] CHIP:DMG: [ [1634582528.318715][21063:21070] CHIP:DMG: CommandDataElement = [1634582528.318781][21063:21070] CHIP:DMG: { [1634582528.318837][21063:21070] CHIP:DMG: CommandPath = [1634582528.318904][21063:21070] CHIP:DMG: { [1634582528.318980][21063:21070] CHIP:DMG: EndpointId = 0x0, [1634582528.319060][21063:21070] CHIP:DMG: ClusterId = 0x30, [1634582528.319136][21063:21070] CHIP:DMG: CommandId = 0x2, [1634582528.319204][21063:21070] CHIP:DMG: }, [1634582528.319278][21063:21070] CHIP:DMG: [1634582528.319338][21063:21070] CHIP:DMG: StatusElement = [1634582528.319409][21063:21070] CHIP:DMG: { [1634582528.319483][21063:21070] CHIP:DMG: GeneralCode = 0x0, [1634582528.319556][21063:21070] CHIP:DMG: ProtocolId = 0x1, [1634582528.319633][21063:21070] CHIP:DMG: protocolCode = 0x0, [1634582528.319705][21063:21070] CHIP:DMG: }, [1634582528.319774][21063:21070] CHIP:DMG: [1634582528.319832][21063:21070] CHIP:DMG: }, [1634582528.319903][21063:21070] CHIP:DMG: [1634582528.319954][21063:21070] CHIP:DMG: ], [1634582528.320017][21063:21070] CHIP:DMG: [1634582528.320065][21063:21070] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582528.320626][21063:21070] CHIP:ZCL: DefaultResponse: [1634582528.320679][21063:21070] CHIP:ZCL: Transaction: 0xffffb93a13a0 [1634582528.320779][21063:21070] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582528.320837][21063:21070] CHIP:CTL: Received success response 0xb814 [1634582528.320908][21063:21070] CHIP:CTL: Exchanging certificates [1634582528.320952][21063:21070] CHIP:CTL: Sending OpCSR request to 0x38881100 device [1634582528.321110][21063:21070] CHIP:DMG: ICR moving to [Initialize] [1634582528.321192][21063:21070] CHIP:DMG: ICR moving to [AddCommand] [1634582528.321416][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 3 [1634582528.321476][21063:21070] CHIP:IN: Build encrypted message 0x388dacf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 28802r with MessageCounter 3. [1634582528.321547][21063:21070] CHIP:IN: Sending encrypted msg 0x388dacf8 to 0x0000000000BC614E at utc time: 2212492 msec [1634582528.321599][21063:21070] CHIP:IN: Sending msg on generic transport [1634582528.321787][21063:21070] CHIP:DMG: ICR moving to [ Sending] [1634582528.321844][21063:21070] CHIP:CTL: Sent OpCSR request, waiting for the CSR [1634582528.322001][21063:21070] CHIP:DMG: ICR moving to [Uninitiali] [1634582528.322066][21063:21070] CHIP:EM: Sending Standalone Ack for MessageCounter:00000002 [1634582528.322188][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 4 [1634582528.322243][21063:21070] CHIP:IN: Build encrypted message 0xffffb17adad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 28801r with MessageCounter 4. [1634582528.322312][21063:21070] CHIP:IN: Sending encrypted msg 0xffffb17adad0 to 0x0000000000BC614E at utc time: 2212493 msec [1634582528.322365][21063:21070] CHIP:IN: Sending msg on generic transport [1634582528.322508][21063:21070] CHIP:EM: Flushed pending ack for MessageCounter:00000002 [1634582529.129043][21063:21070] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 28802i [1634582529.129182][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:00000003 from Retrans Table [1634582529.129232][21063:21070] CHIP:EM: Removed CHIP MessageCounter:00000003 from RetransTable [1634582529.129330][21063:21070] CHIP:DMG: InvokeCommand = [1634582529.129383][21063:21070] CHIP:DMG: { [1634582529.129424][21063:21070] CHIP:DMG: CommandList = [1634582529.129474][21063:21070] CHIP:DMG: [ [1634582529.129521][21063:21070] CHIP:DMG: CommandDataElement = [1634582529.129588][21063:21070] CHIP:DMG: { [1634582529.129641][21063:21070] CHIP:DMG: CommandPath = [1634582529.129702][21063:21070] CHIP:DMG: { [1634582529.129770][21063:21070] CHIP:DMG: EndpointId = 0x0, [1634582529.129841][21063:21070] CHIP:DMG: ClusterId = 0x3e, [1634582529.129904][21063:21070] CHIP:DMG: CommandId = 0x5, [1634582529.129969][21063:21070] CHIP:DMG: }, [1634582529.130037][21063:21070] CHIP:DMG: [1634582529.130090][21063:21070] CHIP:DMG: CommandData = [1634582529.130152][21063:21070] CHIP:DMG: { [1634582529.130219][21063:21070] CHIP:DMG: 0x0 = [ [1634582529.130326][21063:21070] 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, [1634582529.130396][21063:21070] CHIP:DMG: ] [1634582529.130451][21063:21070] CHIP:DMG: 0x1 = [ [1634582529.130507][21063:21070] CHIP:DMG: [1634582529.130567][21063:21070] CHIP:DMG: ] [1634582529.130625][21063:21070] CHIP:DMG: }, [1634582529.130681][21063:21070] CHIP:DMG: }, [1634582529.130745][21063:21070] CHIP:DMG: [1634582529.130791][21063:21070] CHIP:DMG: ], [1634582529.130849][21063:21070] CHIP:DMG: [1634582529.130891][21063:21070] CHIP:DMG: } [1634582529.131015][21063:21070] CHIP:ZCL: Received Cluster Command: Cluster=3e Command=5 Endpoint=0 [1634582529.131077][21063:21070] CHIP:ZCL: OpCSRResponse: [1634582529.131119][21063:21070] CHIP:ZCL: NOCSRElements: 254 [1634582529.131157][21063:21070] CHIP:ZCL: AttestationSignature: 0 [1634582529.131205][21063:21070] CHIP:CTL: Received certificate signing request from the device [1634582529.131249][21063:21070] CHIP:CTL: Getting certificate chain for the device from the issuer [1634582529.131289][21063:21070] CHIP:CTL: Verifying Certificate Signing Request [1634582529.132620][21063:21070] CHIP:CTL: Generating NOC [1634582529.133217][21063:21070] CHIP:CTL: Generating ICAC [1634582529.133648][21063:21070] CHIP:CTL: Providing certificate chain to the commissioner [1634582529.133700][21063:21070] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:183: Success [1634582529.133894][21063:21070] CHIP:CTL: Sending root certificate to the device [1634582529.133979][21063:21070] CHIP:DMG: ICR moving to [Initialize] [1634582529.134041][21063:21070] CHIP:DMG: ICR moving to [AddCommand] [1634582529.134251][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 5 [1634582529.134301][21063:21070] CHIP:IN: Build encrypted message 0x388dacf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 28803r with MessageCounter 5. [1634582529.134358][21063:21070] CHIP:IN: Sending encrypted msg 0x388dacf8 to 0x0000000000BC614E at utc time: 2213305 msec [1634582529.134401][21063:21070] CHIP:IN: Sending msg on generic transport [1634582529.134568][21063:21070] CHIP:DMG: ICR moving to [ Sending] [1634582529.134615][21063:21070] CHIP:CTL: Sent root certificate to the device [1634582529.134955][21063:21070] CHIP:DMG: ICR moving to [Uninitiali] [1634582529.135018][21063:21070] CHIP:EM: Sending Standalone Ack for MessageCounter:00000003 [1634582529.135117][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 6 [1634582529.135162][21063:21070] CHIP:IN: Build encrypted message 0xffffb17adad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 28802r with MessageCounter 6. [1634582529.135219][21063:21070] CHIP:IN: Sending encrypted msg 0xffffb17adad0 to 0x0000000000BC614E at utc time: 2213306 msec [1634582529.135262][21063:21070] CHIP:IN: Sending msg on generic transport [1634582529.135382][21063:21070] CHIP:EM: Flushed pending ack for MessageCounter:00000003 [1634582529.213466][21063:21070] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 28803i [1634582529.213570][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:00000005 from Retrans Table [1634582529.213596][21063:21070] CHIP:EM: Removed CHIP MessageCounter:00000005 from RetransTable [1634582529.213662][21063:21070] CHIP:DMG: InvokeCommand = [1634582529.213691][21063:21070] CHIP:DMG: { [1634582529.213714][21063:21070] CHIP:DMG: CommandList = [1634582529.213741][21063:21070] CHIP:DMG: [ [1634582529.213766][21063:21070] CHIP:DMG: CommandDataElement = [1634582529.213796][21063:21070] CHIP:DMG: { [1634582529.213822][21063:21070] CHIP:DMG: CommandPath = [1634582529.213861][21063:21070] CHIP:DMG: { [1634582529.213895][21063:21070] CHIP:DMG: EndpointId = 0x0, [1634582529.213934][21063:21070] CHIP:DMG: ClusterId = 0x3e, [1634582529.213969][21063:21070] CHIP:DMG: CommandId = 0xb, [1634582529.214000][21063:21070] CHIP:DMG: }, [1634582529.214038][21063:21070] CHIP:DMG: [1634582529.214067][21063:21070] CHIP:DMG: StatusElement = [1634582529.214099][21063:21070] CHIP:DMG: { [1634582529.214132][21063:21070] CHIP:DMG: GeneralCode = 0x0, [1634582529.214169][21063:21070] CHIP:DMG: ProtocolId = 0x1, [1634582529.214202][21063:21070] CHIP:DMG: protocolCode = 0x0, [1634582529.214237][21063:21070] CHIP:DMG: }, [1634582529.214269][21063:21070] CHIP:DMG: [1634582529.214297][21063:21070] CHIP:DMG: }, [1634582529.214329][21063:21070] CHIP:DMG: [1634582529.214354][21063:21070] CHIP:DMG: ], [1634582529.214384][21063:21070] CHIP:DMG: [1634582529.214407][21063:21070] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582529.214782][21063:21070] CHIP:ZCL: DefaultResponse: [1634582529.214810][21063:21070] CHIP:ZCL: Transaction: 0xffffb93a13a0 [1634582529.214832][21063:21070] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582529.214861][21063:21070] CHIP:CTL: Device confirmed that it has received the root certificate [1634582529.214884][21063:21070] CHIP:CTL: Sending operational certificate chain to the device [1634582529.214942][21063:21070] CHIP:DMG: ICR moving to [Initialize] [1634582529.214993][21063:21070] CHIP:DMG: ICR moving to [AddCommand] [1634582529.215166][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 7 [1634582529.215199][21063:21070] CHIP:IN: Build encrypted message 0x388dacf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 28804r with MessageCounter 7. [1634582529.215237][21063:21070] CHIP:IN: Sending encrypted msg 0x388dacf8 to 0x0000000000BC614E at utc time: 2213386 msec [1634582529.215262][21063:21070] CHIP:IN: Sending msg on generic transport [1634582529.215383][21063:21070] CHIP:DMG: ICR moving to [ Sending] [1634582529.215415][21063:21070] CHIP:CTL: Sent operational certificate to the device [1634582529.215516][21063:21070] CHIP:DMG: ICR moving to [Uninitiali] [1634582529.215551][21063:21070] CHIP:EM: Sending Standalone Ack for MessageCounter:00000004 [1634582529.215621][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 8 [1634582529.215648][21063:21070] CHIP:IN: Build encrypted message 0xffffb17adad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 28803r with MessageCounter 8. [1634582529.215682][21063:21070] CHIP:IN: Sending encrypted msg 0xffffb17adad0 to 0x0000000000BC614E at utc time: 2213386 msec [1634582529.215708][21063:21070] CHIP:IN: Sending msg on generic transport [1634582529.215785][21063:21070] CHIP:EM: Flushed pending ack for MessageCounter:00000004 [1634582531.690359][21063:21070] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 28804i [1634582531.690458][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:00000007 from Retrans Table [1634582531.690485][21063:21070] CHIP:EM: Removed CHIP MessageCounter:00000007 from RetransTable [1634582531.690552][21063:21070] CHIP:DMG: InvokeCommand = [1634582531.690582][21063:21070] CHIP:DMG: { [1634582531.690604][21063:21070] CHIP:DMG: CommandList = [1634582531.690632][21063:21070] CHIP:DMG: [ [1634582531.690656][21063:21070] CHIP:DMG: CommandDataElement = [1634582531.690694][21063:21070] CHIP:DMG: { [1634582531.690721][21063:21070] CHIP:DMG: CommandPath = [1634582531.690752][21063:21070] CHIP:DMG: { [1634582531.690782][21063:21070] CHIP:DMG: EndpointId = 0x0, [1634582531.690816][21063:21070] CHIP:DMG: ClusterId = 0x3e, [1634582531.690850][21063:21070] CHIP:DMG: CommandId = 0x8, [1634582531.690883][21063:21070] CHIP:DMG: }, [1634582531.690919][21063:21070] CHIP:DMG: [1634582531.690948][21063:21070] CHIP:DMG: CommandData = [1634582531.690980][21063:21070] CHIP:DMG: { [1634582531.691013][21063:21070] CHIP:DMG: 0x0 = 0, [1634582531.691049][21063:21070] CHIP:DMG: 0x1 = 3, [1634582531.691084][21063:21070] CHIP:DMG: 0x2 = [ [1634582531.691116][21063:21070] CHIP:DMG: [1634582531.691151][21063:21070] CHIP:DMG: ] [1634582531.691185][21063:21070] CHIP:DMG: }, [1634582531.691213][21063:21070] CHIP:DMG: }, [1634582531.691248][21063:21070] CHIP:DMG: [1634582531.691272][21063:21070] CHIP:DMG: ], [1634582531.691303][21063:21070] CHIP:DMG: [1634582531.691326][21063:21070] CHIP:DMG: } [1634582531.691379][21063:21070] CHIP:ZCL: Received Cluster Command: Cluster=3e Command=8 Endpoint=0 [1634582531.691414][21063:21070] CHIP:ZCL: NOCResponse: [1634582531.691437][21063:21070] CHIP:ZCL: StatusCode: 0 [1634582531.691458][21063:21070] CHIP:ZCL: FabricIndex: 3 [1634582531.691483][21063:21070] CHIP:ZCL: DebugText: 0 [1634582531.691510][21063:21070] CHIP:CTL: Device returned status 0 on receiving the NOC [1634582531.691535][21063:21070] CHIP:CTL: Operational credentials provisioned on device 0x38881100 [1634582531.691558][21063:21070] CHIP:CTL: Enabling Network [1634582531.691609][21063:21070] CHIP:DMG: ICR moving to [Initialize] [1634582531.691655][21063:21070] CHIP:DMG: ICR moving to [AddCommand] [1634582531.691776][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 9 [1634582531.691806][21063:21070] CHIP:IN: Build encrypted message 0x388dacf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 28805r with MessageCounter 9. [1634582531.691842][21063:21070] CHIP:IN: Sending encrypted msg 0x388dacf8 to 0x0000000000BC614E at utc time: 2215863 msec [1634582531.691867][21063:21070] CHIP:IN: Sending msg on generic transport [1634582531.691979][21063:21070] CHIP:DMG: ICR moving to [ Sending] [1634582531.692097][21063:21070] CHIP:DMG: ICR moving to [Uninitiali] [1634582531.692132][21063:21070] CHIP:EM: Sending Standalone Ack for MessageCounter:00000005 [1634582531.692196][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 10 [1634582531.692222][21063:21070] CHIP:IN: Build encrypted message 0xffffb17adad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 28804r with MessageCounter 10. [1634582531.692257][21063:21070] CHIP:IN: Sending encrypted msg 0xffffb17adad0 to 0x0000000000BC614E at utc time: 2215863 msec [1634582531.692282][21063:21070] CHIP:IN: Sending msg on generic transport [1634582531.692366][21063:21070] CHIP:EM: Flushed pending ack for MessageCounter:00000005 [1634582532.303760][21063:21070] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 28805i [1634582532.303900][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:00000009 from Retrans Table [1634582532.303950][21063:21070] CHIP:EM: Removed CHIP MessageCounter:00000009 from RetransTable [1634582532.304046][21063:21070] CHIP:DMG: InvokeCommand = [1634582532.304100][21063:21070] CHIP:DMG: { [1634582532.304142][21063:21070] CHIP:DMG: CommandList = [1634582532.304193][21063:21070] CHIP:DMG: [ [1634582532.304240][21063:21070] CHIP:DMG: CommandDataElement = [1634582532.304292][21063:21070] CHIP:DMG: { [1634582532.304341][21063:21070] CHIP:DMG: CommandPath = [1634582532.304409][21063:21070] CHIP:DMG: { [1634582532.304470][21063:21070] CHIP:DMG: EndpointId = 0x0, [1634582532.304543][21063:21070] CHIP:DMG: ClusterId = 0x31, [1634582532.304607][21063:21070] CHIP:DMG: CommandId = 0xc, [1634582532.304671][21063:21070] CHIP:DMG: }, [1634582532.304768][21063:21070] CHIP:DMG: [1634582532.304824][21063:21070] CHIP:DMG: StatusElement = [1634582532.304883][21063:21070] CHIP:DMG: { [1634582532.304943][21063:21070] CHIP:DMG: GeneralCode = 0x0, [1634582532.305012][21063:21070] CHIP:DMG: ProtocolId = 0x1, [1634582532.305069][21063:21070] CHIP:DMG: protocolCode = 0x0, [1634582532.305129][21063:21070] CHIP:DMG: }, [1634582532.305192][21063:21070] CHIP:DMG: [1634582532.305241][21063:21070] CHIP:DMG: }, [1634582532.305303][21063:21070] CHIP:DMG: [1634582532.305348][21063:21070] CHIP:DMG: ], [1634582532.305405][21063:21070] CHIP:DMG: [1634582532.305447][21063:21070] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582532.305964][21063:21070] CHIP:ZCL: DefaultResponse: [1634582532.306014][21063:21070] CHIP:ZCL: Transaction: 0xffffb93a13a0 [1634582532.306056][21063:21070] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582532.306106][21063:21070] CHIP:CTL: Received success response 0xb814 [1634582532.306169][21063:21070] CHIP:CTL: Finding node on operational network [1634582532.308066][21063:21070] CHIP:DMG: ICR moving to [Uninitiali] [1634582532.308156][21063:21070] CHIP:EM: Sending Standalone Ack for MessageCounter:00000006 [1634582532.308321][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 11 [1634582532.308377][21063:21070] CHIP:IN: Build encrypted message 0xffffb17adad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 28805r with MessageCounter 11. [1634582532.308448][21063:21070] CHIP:IN: Sending encrypted msg 0xffffb17adad0 to 0x0000000000BC614E at utc time: 2216479 msec [1634582532.308497][21063:21070] CHIP:IN: Sending msg on generic transport [1634582532.308775][21063:21070] CHIP:EM: Flushed pending ack for MessageCounter:00000006 [1634582532.309934][21063:21070] CHIP:DL: Avahi resolve found [1634582532.310068][21063:21070] CHIP:DIS: Node ID resolved for 0x0000000000BC614E to [192.168.1.111]:5540 [1634582532.310200][21063:21070] CHIP:CTL: SyncSetKeyValue on PairedDevicebc614e Node address has been updated [1634582532.310360][21063:21070] CHIP:CTL: OperationalDiscoveryComplete for device ID 12345678 [1634582532.310407][21063:21070] CHIP:CTL: Enabling CASE session establishment for the device [1634582532.310475][21063:21070] CHIP:CTL: SyncSetKeyValue on PairedDevicebc614e [1634582532.310524][21063:21070] CHIP:IN: Marking old secure session for device 0x0000000000BC614E as expired [1634582532.310610][21063:21070] CHIP:CTL: SyncSetKeyValue on PairedDevicebc614e [1634582532.310660][21063:21070] CHIP:CTL: SyncSetKeyValue on StartKeyID [1634582532.311639][21063:21070] CHIP:IN: Build plaintext message 0x388dacf8 to 0x0000000000000000 of type 48 and protocolId 0 on exchange 28806r with MessageCounter 1445407241. [1634582532.311734][21063:21070] CHIP:IN: Sending plaintext msg 0x388dacf8 to 0x0000000000000000 at utc time: 2216483 msec [1634582532.311801][21063:21070] CHIP:IN: Sending msg on generic transport [1634582532.311999][21063:21070] CHIP:SC: Sent SigmaR1 msg [1634582534.358594][21063:21070] CHIP:EM: Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 28806i [1634582534.358745][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:56272A09 from Retrans Table [1634582534.358861][21063:21070] CHIP:EM: Removed CHIP MessageCounter:56272A09 from RetransTable [1634582534.358982][21063:21070] CHIP:SC: Received SigmaR2 msg [1634582534.359059][21063:21070] CHIP:SC: Peer assigned session key ID 7 [1634582534.366989][21063:21070] CHIP:SC: Sending SigmaR3 [1634582534.367889][21063:21070] CHIP:EM: Piggybacking Ack for MessageCounter:D5A8C03B on exchange: 28806i [1634582534.368199][21063:21070] CHIP:IN: Build plaintext message 0x388dacf8 to 0x0000000000000000 of type 50 and protocolId 0 on exchange 28806r with MessageCounter 1445407242. [1634582534.368297][21063:21070] CHIP:IN: Sending plaintext msg 0x388dacf8 to 0x0000000000000000 at utc time: 2218539 msec [1634582534.368472][21063:21070] CHIP:IN: Sending msg on generic transport [1634582534.368756][21063:21070] CHIP:SC: Sent SigmaR3 msg [1634582534.368841][21063:21070] CHIP:IN: New secure session created for device 0x0000000000BC614E, key 7!! [1634582534.369018][21063:21070] CHIP:CTL: Calling commissioning complete [1634582534.369120][21063:21070] CHIP:DMG: ICR moving to [Initialize] [1634582534.369205][21063:21070] CHIP:DMG: ICR moving to [AddCommand] [1634582534.369408][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 0 [1634582534.369479][21063:21070] CHIP:IN: Build encrypted message 0x388dad10 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 28807r with MessageCounter 0. [1634582534.369560][21063:21070] CHIP:IN: Sending encrypted msg 0x388dad10 to 0x0000000000BC614E at utc time: 2218540 msec [1634582534.369621][21063:21070] CHIP:IN: Sending msg on generic transport [1634582534.369798][21063:21070] CHIP:DMG: ICR moving to [ Sending] [1634582537.251443][21063:21070] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 28806i [1634582537.251600][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:56272A0A from Retrans Table [1634582537.251665][21063:21070] CHIP:EM: Removed CHIP MessageCounter:56272A0A from RetransTable [1634582537.319347][21063:21070] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 28807i [1634582537.319486][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:00000000 from Retrans Table [1634582537.319535][21063:21070] CHIP:EM: Removed CHIP MessageCounter:00000000 from RetransTable [1634582537.319632][21063:21070] CHIP:DMG: InvokeCommand = [1634582537.319684][21063:21070] CHIP:DMG: { [1634582537.319726][21063:21070] CHIP:DMG: CommandList = [1634582537.319777][21063:21070] CHIP:DMG: [ [1634582537.319824][21063:21070] CHIP:DMG: CommandDataElement = [1634582537.319877][21063:21070] CHIP:DMG: { [1634582537.319937][21063:21070] CHIP:DMG: CommandPath = [1634582537.319998][21063:21070] CHIP:DMG: { [1634582537.320059][21063:21070] CHIP:DMG: EndpointId = 0x0, [1634582537.320130][21063:21070] CHIP:DMG: ClusterId = 0x30, [1634582537.320193][21063:21070] CHIP:DMG: CommandId = 0x4, [1634582537.320251][21063:21070] CHIP:DMG: }, [1634582537.320320][21063:21070] CHIP:DMG: [1634582537.320375][21063:21070] CHIP:DMG: StatusElement = [1634582537.320430][21063:21070] CHIP:DMG: { [1634582537.320503][21063:21070] CHIP:DMG: GeneralCode = 0x0, [1634582537.320595][21063:21070] CHIP:DMG: ProtocolId = 0x1, [1634582537.320685][21063:21070] CHIP:DMG: protocolCode = 0x0, [1634582537.320825][21063:21070] CHIP:DMG: }, [1634582537.321017][21063:21070] CHIP:DMG: [1634582537.321092][21063:21070] CHIP:DMG: }, [1634582537.321178][21063:21070] CHIP:DMG: [1634582537.321239][21063:21070] CHIP:DMG: ], [1634582537.321316][21063:21070] CHIP:DMG: [1634582537.321373][21063:21070] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634582537.322064][21063:21070] CHIP:ZCL: DefaultResponse: [1634582537.322128][21063:21070] CHIP:ZCL: Transaction: 0xffffb93a1240 [1634582537.322183][21063:21070] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634582537.322246][21063:21070] CHIP:CTL: Received success response 0xb814 [1634582537.322331][21063:21070] CHIP:CTL: Rendezvous cleanup [1634582537.322472][21063:21070] CHIP:CTL: SyncSetKeyValue on PairedDevicebc614e [1634582537.322787][21063:21070] CHIP:CTL: SyncSetKeyValue on ListPairedDevices0 [1634582537.322863][21063:21070] CHIP:CTL: SyncSetKeyValue on StartKeyID [1634582537.322954][21063:21070] CHIP:CTL: SyncSetKeyValue on PairedDevicebc614e Secure Session to Device Established Device temporary node id (**this does not match spec**): 12345678 [1634582537.323466][21063:21070] CHIP:DMG: ICR moving to [Uninitiali] [1634582537.323664][21063:21070] CHIP:EM: Sending Standalone Ack for MessageCounter:00000001 chip-device-ctrl > [1634582537.323853][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 1 [1634582537.323924][21063:21070] CHIP:IN: Build encrypted message 0xffffb17adad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 28807r with MessageCounter 1. [1634582537.324015][21063:21070] CHIP:IN: Sending encrypted msg 0xffffb17adad0 to 0x0000000000BC614E at utc time: 2221495 msec [1634582537.324081][21063:21070] CHIP:IN: Sending msg on generic transport [1634582537.324284][21063:21070] CHIP:EM: Flushed pending ack for MessageCounter:00000001 Read Vendor Name from CR2 chip-device-ctrl > zclread Basic VendorName 12345678 0 0 [1634582543.936678][21063:21070] CHIP:IN: Build plaintext message 0x388dacf8 to 0x0000000000000000 of type 48 and protocolId 0 on exchange 28808r with MessageCounter 1445407243. [1634582543.936864][21063:21070] CHIP:IN: Sending plaintext msg 0x388dacf8 to 0x0000000000000000 at utc time: 2228108 msec [1634582543.936933][21063:21070] CHIP:IN: Sending msg on generic transport [1634582543.937196][21063:21070] CHIP:SC: Sent SigmaR1 msg [1634582543.937298][21063:21070] CHIP:DMG: SendReadRequest: Client[0] [ INIT] [1634582543.937541][21063:21070] CHIP:IN: Secure message was encrypted: Msg ID 2 [1634582543.937611][21063:21070] CHIP:IN: Build encrypted message 0x388dad10 to 0x0000000000BC614E of type 2 and protocolId 1 on exchange 28809r with MessageCounter 2. [1634582543.937691][21063:21070] CHIP:IN: Sending encrypted msg 0x388dad10 to 0x0000000000BC614E at utc time: 2228108 msec [1634582543.937756][21063:21070] CHIP:IN: Sending msg on generic transport [1634582543.937929][21063:21070] CHIP:DMG: Client[0] moving to [AwaitingInitialReport] [1634582545.421124][21063:21070] CHIP:EM: Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 28808i [1634582545.421280][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:56272A0B from Retrans Table [1634582545.421344][21063:21070] CHIP:EM: Removed CHIP MessageCounter:56272A0B from RetransTable [1634582545.421454][21063:21070] CHIP:SC: Received SigmaR2 msg [1634582545.421548][21063:21070] CHIP:SC: Peer assigned session key ID 9 [1634582545.427814][21063:21070] CHIP:SC: Sending SigmaR3 [1634582545.428556][21063:21070] CHIP:EM: Piggybacking Ack for MessageCounter:D5A8C03D on exchange: 28808i [1634582545.428666][21063:21070] CHIP:IN: Build plaintext message 0x388dacf8 to 0x0000000000000000 of type 50 and protocolId 0 on exchange 28808r with MessageCounter 1445407244. [1634582545.428779][21063:21070] CHIP:IN: Sending plaintext msg 0x388dacf8 to 0x0000000000000000 at utc time: 2229600 msec [1634582545.428833][21063:21070] CHIP:IN: Sending msg on generic transport [1634582545.429052][21063:21070] CHIP:SC: Sent SigmaR3 msg [1634582545.429120][21063:21070] CHIP:IN: New secure session created for device 0x0000000000BC614E, key 9!! [1634582547.704517][21063:21070] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 28808i [1634582547.704676][21063:21070] CHIP:EM: Rxd Ack; Removing MessageCounter:56272A0C from Retrans Table [1634582547.704833][21063:21070] CHIP:EM: Removed CHIP MessageCounter:56272A0C from RetransTable [1634582548.901274][21063:21070] CHIP:IN: Sending encrypted msg 0x388dad10 to 0x0000000000BC614E at utc time: 2233072 msec [1634582548.901337][21063:21070] CHIP:IN: Sending msg on generic transport [1634582548.901489][21063:21070] CHIP:EM: Retransmit MessageCounter:00000002 Send Cnt 1 [1634582549.156947][21063:21070] CHIP:IN: Sending encrypted msg 0x388dad10 to 0x0000000000BC614E at utc time: 2233328 msec [1634582549.157016][21063:21070] CHIP:IN: Sending msg on generic transport [1634582549.157186][21063:21070] CHIP:EM: Retransmit MessageCounter:00000002 Send Cnt 2 [1634582549.412839][21063:21070] CHIP:IN: Sending encrypted msg 0x388dad10 to 0x0000000000BC614E at utc time: 2233584 msec [1634582549.412924][21063:21070] CHIP:IN: Sending msg on generic transport [1634582549.413136][21063:21070] CHIP:EM: Retransmit MessageCounter:00000002 Send Cnt 3 [1634582549.668648][21063:21070] CHIP:EM: Failed to Send CHIP MessageCounter:00000002 sendCount: 3 max retries: 3 [1634582555.941359][21063:21070] CHIP:DMG: Time out! failed to receive report data from Exchange: 28809i [1634582555.941469][21063:21070] CHIP:ZCL: ReadAttributesResponse: [1634582555.941527][21063:21070] CHIP:ZCL: ClusterId: 0x0000_0000 [1634582555.941592][21063:21070] CHIP:ZCL: attributeId: 0x0000_0000 [1634582555.941659][21063:21070] CHIP:ZCL: status: Failure (0x0001) [1634582555.941856][21063:21070] CHIP:DMG: Client[0] moving to [UNINIT] An exception occurred during reading ZCL attribute: CHIP Error 0x00000001: Sending blocked Read Vendor Name from CR1 chip-device-ctrl > zclread Basic VendorName 12344321 0 0 [1634583075.276580][24228:24235] CHIP:DMG: SendReadRequest: Client[0] [ INIT] [1634583075.276928][24228:24235] CHIP:IN: Secure message was encrypted: Msg ID 6 [1634583075.277005][24228:24235] CHIP:IN: Build encrypted message 0x119f5cf8 to 0x0000000000BC5C01 of type 2 and protocolId 1 on exchange 20434r with MessageCounter 6. [1634583075.277093][24228:24235] CHIP:IN: Sending encrypted msg 0x119f5cf8 to 0x0000000000BC5C01 at utc time: 3061559 msec [1634583075.277157][24228:24235] CHIP:IN: Sending msg on generic transport [1634583075.277644][24228:24235] CHIP:DMG: Client[0] moving to [AwaitingInitialReport] [1634583080.212271][24228:24235] CHIP:IN: Sending encrypted msg 0x119f5cf8 to 0x0000000000BC5C01 at utc time: 3066494 msec [1634583080.212377][24228:24235] CHIP:IN: Sending msg on generic transport [1634583080.212678][24228:24235] CHIP:EM: Retransmit MessageCounter:00000006 Send Cnt 1 [1634583080.465250][24228:24235] CHIP:IN: Sending encrypted msg 0x119f5cf8 to 0x0000000000BC5C01 at utc time: 3066747 msec [1634583080.465334][24228:24235] CHIP:IN: Sending msg on generic transport [1634583080.465609][24228:24235] CHIP:EM: Retransmit MessageCounter:00000006 Send Cnt 2 [1634583080.721253][24228:24235] CHIP:IN: Sending encrypted msg 0x119f5cf8 to 0x0000000000BC5C01 at utc time: 3067003 msec [1634583080.721347][24228:24235] CHIP:IN: Sending msg on generic transport [1634583080.721629][24228:24235] CHIP:EM: Retransmit MessageCounter:00000006 Send Cnt 3 [1634583080.977178][24228:24235] CHIP:EM: Failed to Send CHIP MessageCounter:00000006 sendCount: 3 max retries: 3 [1634583087.277117][24228:24235] CHIP:DMG: Time out! failed to receive report data from Exchange: 20434i [1634583087.277201][24228:24235] CHIP:ZCL: ReadAttributesResponse: [1634583087.277241][24228:24235] CHIP:ZCL: ClusterId: 0x0000_0000 [1634583087.277291][24228:24235] CHIP:ZCL: attributeId: 0x0000_0000 [1634583087.277334][24228:24235] CHIP:ZCL: status: Failure (0x0001) [1634583087.277544][24228:24235] CHIP:DMG: Client[0] moving to [UNINIT] An exception occurred during reading ZCL attribute: CHIP Error 0x00000001: Sending blocked chip-device-ctrl > Read Vendor Name from CR3 chip-device-ctrl > zclread Basic VendorName 43214321 0 0 [1634582580219] [16891:803304] CHIP: [DMG] SendReadRequest: Client[0] [ INIT] [1634582580220] [16891:803304] CHIP: [IN] Secure message was encrypted: Msg ID 4 [1634582580220] [16891:803304] CHIP: [IN] Build encrypted message 0x7fd4bc8bc058 to 0x00000000029365F1 of type 2 and protocolId 1 on exchange 30731r with MessageCounter 4. [1634582580220] [16891:803304] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 235025909 msec [1634582580220] [16891:803304] CHIP: [IN] Sending msg on generic transport [1634582580220] [16891:803304] CHIP: [DMG] Client[0] moving to [AwaitingInitialReport] [1634582585190] [16891:803304] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 235030879 msec [1634582585190] [16891:803304] CHIP: [IN] Sending msg on generic transport [1634582585190] [16891:803304] CHIP: [EM] Retransmit MessageCounter:00000004 Send Cnt 1 [1634582585445] [16891:802149] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 235031134 msec [1634582585445] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582585445] [16891:802149] CHIP: [EM] Retransmit MessageCounter:00000004 Send Cnt 2 [1634582585701] [16891:802149] CHIP: [IN] Sending encrypted msg 0x7fd4bc8bc058 to 0x00000000029365F1 at utc time: 235031391 msec [1634582585702] [16891:802149] CHIP: [IN] Sending msg on generic transport [1634582585702] [16891:802149] CHIP: [EM] Retransmit MessageCounter:00000004 Send Cnt 3 [1634582585958] [16891:802149] CHIP: [EM] Failed to Send CHIP MessageCounter:00000004 sendCount: 3 max retries: 3 [1634582592230] [16891:802149] CHIP: [DMG] Time out! failed to receive report data from Exchange: 30731i [1634582592230] [16891:802149] CHIP: [ZCL] ReadAttributesResponse: [1634582592230] [16891:802149] CHIP: [ZCL] ClusterId: 0x0000_0000 [1634582592230] [16891:802149] CHIP: [ZCL] attributeId: 0x0000_0000 [1634582592230] [16891:802149] CHIP: [ZCL] status: Failure (0x0001) [1634582592230] [16891:802149] CHIP: [DMG] Client[0] moving to [UNINIT] An exception occurred during reading ZCL attribute: CHIP Error 0x00000001: Sending blocked DUT logs CHIP:P6: Unknown cluster ID: 62 CHIP:EM: Piggybacking Ack for MessageCounter:56272A0B on exchange: 28808r CHIP:IN: Build plaintext message 0x8018780 to 0x0000000000000000 of type 49 and protocolId 0 on exchange 28808i with MessageCounter 3584606269. CHIP:IN: Sending plaintext msg 0x8018780 to 0x0000000000000000 at utc time: ld msec CHIP:IN: Sending msg on generic transport CHIP:SC: Sent SigmaR2 msg CHIP:DL: Long dispatch time: 1430 ms, for event type 4 CHIP:EM: Received message of type 0x02 with vendorId 0x0000 and protocolId 0x0001 on exchange 28809r CHIP:EM: Handling via exchange: 28809r, Delegate: 0x0x80158a0 CHIP:-: Receive Read request CHIP:DMG: IM RH moving to [Initialized] CHIP:DMG: IM RH moving to [GeneratingReports] CHIP:EM: Received message of type 0x32 with vendorId 0x0000 and protocolId 0x0000 on exchange 28808r CHIP:EM: Rxd Ack; Removing MessageCounter:D5A8C03D from Retrans Table CHIP:EM: Removed CHIP MessageCounter:D5A8C03D from RetransTable CHIP:SC: Received SigmaR3 msg 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:56272A0C CHIP:IN: Build plaintext message 0x8022298 to 0x0000000000000000 of type 16 and protocolId 0 on exchange 28808i with MessageCounter 3584606270. CHIP:IN: Sending plaintext msg 0x8022298 to 0x0000000000000000 at utc time: ld msec CHIP:IN: Sending msg on generic transport CHIP:EM: Flushed pending ack for MessageCounter:56272A0C CHIP:DL: Long dispatch time: 2274 ms, for event type 4 CHIP:DMG: Cluster 28, Field 1 is dirty CHIP:DMG: Received Cluster Command: Cluster=0x0000_0028 NodeId=0x0000000000BC614E Endpoint=0 AttributeId=1 ListIndex=0 CHIP:DMG: Sending report...