pi@ubuntu:~$ rm -rf /tmp/chip_* pi@ubuntu:~$ ./chip-tool pairing onnetwork 1 20202021 [1652388147.616958][3606:3606] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1652388147.617216][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_kvs-zEGK3S) [1652388147.617407][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.617792][3606:3606] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1652388147.618010][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-aVwxuS) [1652388147.618179][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1652388147.618291][3606:3606] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1652388147.618471][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_config.ini-ZBRSbR) [1652388147.618588][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388147.618710][3606:3606] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1652388147.618861][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-r7HgQQ) [1652388147.618973][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388147.619241][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-nQlmUR) [1652388147.619753][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1652388147.619803][3606:3606] CHIP:DL: NVS set: chip-factory/unique-id = "90C1089126B7B448" [1652388147.619949][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-qnomvR) [1652388147.624132][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1652388147.624190][3606:3606] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1) [1652388147.624336][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-5G4qlR) [1652388147.624903][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1652388147.624952][3606:3606] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001) [1652388147.625076][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-dUM8QR) [1652388147.625428][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388147.625540][3606:3606] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1) [1652388147.625835][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-2yCpxS) [1652388147.626614][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388147.626681][3606:3606] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1652388147.626877][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-HfSHDR) [1652388147.627556][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388147.627624][3606:3606] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0) [1652388147.627784][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_config.ini-SXOxxS) [1652388147.628374][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388147.628437][3606:3606] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1652388147.628593][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_config.ini-tiCANQ) [1652388147.629242][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388147.629304][3606:3606] CHIP:DL: NVS set: chip-config/location-capability = 0 (0x0) [1652388147.630030][3606:3606] CHIP:DL: Got Ethernet interface: eth0 [1652388147.630647][3606:3606] CHIP:DL: Found the primary Ethernet interface:eth0 [1652388147.631191][3606:3606] CHIP:DL: Got WiFi interface: wlan0 [1652388147.636983][3606:3606] CHIP:DL: Found the primary WiFi interface:wlan0 [1652388147.637087][3606:3606] CHIP:IN: UDP::Init bind&listen port=0 [1652388147.637238][3606:3606] CHIP:IN: UDP::Init bound to port=49625 [1652388147.637271][3606:3606] CHIP:IN: UDP::Init bind&listen port=0 [1652388147.637387][3606:3606] CHIP:IN: UDP::Init bound to port=50618 [1652388147.637417][3606:3606] CHIP:IN: BLEBase::Init - setting/overriding transport [1652388147.637453][3606:3606] CHIP:IN: TransportMgr initialized [1652388147.637494][3606:3606] CHIP:DIS: Init fabric pairing table with server storage [1652388147.637612][3606:3606] CHIP:DIS: Add fabric pairing table delegate [1652388147.639509][3606:3606] CHIP:ZCL: Using ZAP configuration... [1652388147.642440][3606:3606] CHIP:DL: MDNS failed to join multicast group on wpan0 for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1652388147.643654][3606:3606] CHIP:CTL: System State Initialized... [1652388147.643731][3606:3606] CHIP:CTL: Setting attestation nonce to random value [1652388147.643803][3606:3606] CHIP:CTL: Setting CSR nonce to random value [1652388147.643903][3606:3606] CHIP:IN: UDP::Init bind&listen port=5550 [1652388147.644016][3606:3606] CHIP:IN: UDP::Init bound to port=5550 [1652388147.644047][3606:3606] CHIP:IN: UDP::Init bind&listen port=5550 [1652388147.644145][3606:3606] CHIP:IN: UDP::Init bound to port=5550 [1652388147.644243][3606:3606] CHIP:IN: TransportMgr initialized [1652388147.644323][3606:3606] CHIP:CTL: Setting attestation nonce to random value [1652388147.644423][3606:3606] CHIP:CTL: Setting CSR nonce to random value [1652388147.644970][3606:3606] CHIP:CTL: Couldn't get ExampleOpCredsCAKey from storage: ../../examples/chip-tool/config/PersistentStorage.cpp:108: CHIP Error 0x000000A0: Value not found in the persisted storage [1652388147.648295][3606:3606] CHIP:CTL: Couldn't get ExampleOpCredsICAKey from storage: ../../examples/chip-tool/config/PersistentStorage.cpp:108: CHIP Error 0x000000A0: Value not found in the persisted storage [1652388147.649911][3606:3606] CHIP:CTL: Generating RCAC [1652388147.651092][3606:3606] CHIP:CTL: Generating ICAC [1652388147.652370][3606:3606] CHIP:CTL: Generating NOC [1652388147.653527][3606:3606] CHIP:DIS: Verifying the received credentials [1652388147.655947][3606:3606] CHIP:DIS: Added new fabric at index: 0x1, Initialized: 1 [1652388147.655999][3606:3606] CHIP:DIS: Assigned compressed fabric ID: 0x54076DAA023833D1, node ID: 0x000000000001B669 [1652388147.662223][3606:3606] CHIP:DIS: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage [1652388147.663863][3606:3606] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x54076DAA023833D1 [1652388147.663936][3606:3606] CHIP:IN: UDP::Init bind&listen port=5550 [1652388147.664050][3606:3606] CHIP:IN: UDP::Init bound to port=5550 [1652388147.664091][3606:3606] CHIP:IN: UDP::Init bind&listen port=5550 [1652388147.664180][3606:3606] CHIP:IN: UDP::Init bound to port=5550 [1652388147.664203][3606:3606] CHIP:IN: TransportMgr initialized [1652388147.664378][3606:3606] CHIP:CTL: Setting attestation nonce to random value [1652388147.664468][3606:3606] CHIP:CTL: Setting CSR nonce to random value [1652388147.665675][3606:3606] CHIP:CTL: Generating NOC [1652388147.666754][3606:3606] CHIP:DIS: Verifying the received credentials [1652388147.669035][3606:3606] CHIP:DIS: Added new fabric at index: 0x2, Initialized: 1 [1652388147.669081][3606:3606] CHIP:DIS: Assigned compressed fabric ID: 0xBA72F338CA9489BB, node ID: 0x000000000001B669 [1652388147.676661][3606:3606] CHIP:DIS: Fabric (2) persisted to storage. Calling OnFabricPersistedToStorage [1652388147.680924][3606:3606] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xBA72F338CA9489BB [1652388147.681006][3606:3606] CHIP:IN: UDP::Init bind&listen port=5550 [1652388147.681141][3606:3606] CHIP:IN: UDP::Init bound to port=5550 [1652388147.681172][3606:3606] CHIP:IN: UDP::Init bind&listen port=5550 [1652388147.681296][3606:3606] CHIP:IN: UDP::Init bound to port=5550 [1652388147.681325][3606:3606] CHIP:IN: TransportMgr initialized [1652388147.681448][3606:3606] CHIP:CTL: Setting attestation nonce to random value [1652388147.681533][3606:3606] CHIP:CTL: Setting CSR nonce to random value [1652388147.683056][3606:3606] CHIP:CTL: Generating NOC [1652388147.684311][3606:3606] CHIP:DIS: Verifying the received credentials [1652388147.686483][3606:3606] CHIP:DIS: Added new fabric at index: 0x3, Initialized: 1 [1652388147.686527][3606:3606] CHIP:DIS: Assigned compressed fabric ID: 0x682D29C2E3920DF2, node ID: 0x000000000001B669 [1652388147.690866][3606:3606] CHIP:DIS: Fabric (3) persisted to storage. Calling OnFabricPersistedToStorage [1652388147.691749][3606:3606] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x682D29C2E3920DF2 [1652388147.691825][3606:3606] CHIP:IN: UDP::Init bind&listen port=5550 [1652388147.691957][3606:3606] CHIP:IN: UDP::Init bound to port=5550 [1652388147.692004][3606:3606] CHIP:IN: UDP::Init bind&listen port=5550 [1652388147.692112][3606:3606] CHIP:IN: UDP::Init bound to port=5550 [1652388147.692140][3606:3606] CHIP:IN: TransportMgr initialized [1652388147.789381][3606:3611] CHIP:DL: CHIP task running [1652388147.794187][3606:3611] CHIP:TOO: Discovered Device: fd11:33::e65f:1ff:fe6a:fa9f:5540 [1652388147.794430][3606:3611] CHIP:SC: Assigned local session key ID 8738 [1652388147.794508][3606:3611] CHIP:SC: Including MRP parameters in PBKDF param request [1652388147.794577][3606:3611] CHIP:IN: Prepared unauthenticated message 0xaaaaf27f8bc8 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 54982i with MessageCounter:1864588015. [1652388147.794621][3606:3611] CHIP:IN: Sending unauthenticated msg 0xaaaaf27f8bc8 with MessageCounter:1864588015 to 0x0000000000000000 at monotonic time: 00000000013AB0E0 msec [1652388147.794779][3606:3611] CHIP:SC: Sent PBKDF param request [1652388147.794815][3606:3611] CHIP:CTL: Setting attestation nonce to random value [1652388147.794859][3606:3611] CHIP:CTL: Setting CSR nonce to random value [1652388147.794902][3606:3611] CHIP:CTL: Commission called for node ID 0x0000000000000001 [1652388147.803745][3606:3611] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:1378659132 on exchange 54982i [1652388147.803800][3606:3611] CHIP:EM: Found matching exchange: 54982i, Delegate: 0xffff74001750 [1652388147.803855][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:1864588015 from Retrans Table on exchange 54982i [1652388147.803888][3606:3611] CHIP:EM: Removed CHIP MessageCounter:1864588015 from RetransTable on exchange 54982i [1652388147.803933][3606:3611] CHIP:SC: Received PBKDF param response [1652388147.803990][3606:3611] CHIP:SC: Peer assigned session ID 31110 [1652388147.804032][3606:3611] CHIP:SC: Found MRP parameters in the message [1652388147.812380][3606:3611] CHIP:EM: Piggybacking Ack for MessageCounter:1378659132 on exchange: 54982i [1652388147.812560][3606:3611] CHIP:IN: Prepared unauthenticated message 0xaaaaf27f8bc8 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 54982i with MessageCounter:1864588016. [1652388147.812614][3606:3611] CHIP:IN: Sending unauthenticated msg 0xaaaaf27f8bc8 with MessageCounter:1864588016 to 0x0000000000000000 at monotonic time: 00000000013AB0F2 msec [1652388147.812816][3606:3611] CHIP:SC: Sent spake2p msg1 [1652388147.815917][3606:3611] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:1378659133 on exchange 54982i [1652388147.815956][3606:3611] CHIP:EM: Found matching exchange: 54982i, Delegate: 0xffff74001750 [1652388147.815989][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:1864588016 from Retrans Table on exchange 54982i [1652388147.816014][3606:3611] CHIP:EM: Removed CHIP MessageCounter:1864588016 from RetransTable on exchange 54982i [1652388147.816047][3606:3611] CHIP:SC: Received spake2p msg2 [1652388147.817444][3606:3611] CHIP:EM: Piggybacking Ack for MessageCounter:1378659133 on exchange: 54982i [1652388147.817492][3606:3611] CHIP:IN: Prepared unauthenticated message 0xaaaaf27f8bc8 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 54982i with MessageCounter:1864588017. [1652388147.817530][3606:3611] CHIP:IN: Sending unauthenticated msg 0xaaaaf27f8bc8 with MessageCounter:1864588017 to 0x0000000000000000 at monotonic time: 00000000013AB0F7 msec [1652388147.817685][3606:3611] CHIP:SC: Sent spake2p msg3 [1652388147.820028][3606:3611] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:1378659134 on exchange 54982i [1652388147.820062][3606:3611] CHIP:EM: Found matching exchange: 54982i, Delegate: 0xffff74001750 [1652388147.820095][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:1864588017 from Retrans Table on exchange 54982i [1652388147.820119][3606:3611] CHIP:EM: Removed CHIP MessageCounter:1864588017 from RetransTable on exchange 54982i [1652388147.820194][3606:3611] CHIP:IN: New secure session created for device , LSID:8738 PSID:31110! [1652388147.820227][3606:3611] CHIP:CTL: Remote device completed SPAKE2+ handshake [1652388147.820247][3606:3611] CHIP:TOO: Pairing Success [1652388147.820272][3606:3611] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1652388147.820297][3606:3611] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1652388147.820317][3606:3611] CHIP:CTL: Sending request for commissioning information [1652388147.820355][3606:3611] CHIP:DMG: SendReadRequest ReadClient[0xffff740045d0]: Sending Read Request [1652388147.820503][3606:3611] CHIP:IN: Prepared secure message 0xaaaaf27f8bc8 to 0xFFFFFFFB00000000 (0) of type 0x2 and protocolId (0, 1) on exchange 54983i with MessageCounter:4283992. [1652388147.820549][3606:3611] CHIP:IN: Sending encrypted msg 0xaaaaf27f8bc8 with MessageCounter:4283992 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB0FA msec [1652388147.820709][3606:3611] CHIP:DMG: MoveToState ReadClient[0xffff740045d0]: Moving to [AwaitingIn] [1652388147.820754][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1378659134 on exchange 54982i [1652388147.820788][3606:3611] CHIP:IN: Prepared unauthenticated message 0xffff7bffd9d8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54982i with MessageCounter:1864588018. [1652388147.820823][3606:3611] CHIP:IN: Sending unauthenticated msg 0xffff7bffd9d8 with MessageCounter:1864588018 to 0x0000000000000000 at monotonic time: 00000000013AB0FA msec [1652388147.820906][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1378659134 on exchange 54982i [1652388147.841138][3606:3611] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:1691224 on exchange 54983i [1652388147.841212][3606:3611] CHIP:EM: Found matching exchange: 54983i, Delegate: 0xffff740045d0 [1652388147.841273][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:4283992 from Retrans Table on exchange 54983i [1652388147.841310][3606:3611] CHIP:EM: Removed CHIP MessageCounter:4283992 from RetransTable on exchange 54983i [1652388147.841444][3606:3611] CHIP:DMG: ReportDataMessage = [1652388147.841488][3606:3611] CHIP:DMG: { [1652388147.841521][3606:3611] CHIP:DMG: AttributeReportIBs = [1652388147.841578][3606:3611] CHIP:DMG: [ [1652388147.841615][3606:3611] CHIP:DMG: AttributeReportIB = [1652388147.841670][3606:3611] CHIP:DMG: { [1652388147.841713][3606:3611] CHIP:DMG: AttributeDataIB = [1652388147.841768][3606:3611] CHIP:DMG: { [1652388147.841821][3606:3611] CHIP:DMG: DataVersion = 0x441007ae, [1652388147.841870][3606:3611] CHIP:DMG: AttributePathIB = [1652388147.841922][3606:3611] CHIP:DMG: { [1652388147.841974][3606:3611] CHIP:DMG: Endpoint = 0x0, [1652388147.842030][3606:3611] CHIP:DMG: Cluster = 0x31, [1652388147.842125][3606:3611] CHIP:DMG: Attribute = 0x0000_0003, [1652388147.842184][3606:3611] CHIP:DMG: } [1652388147.842241][3606:3611] CHIP:DMG: [1652388147.842295][3606:3611] CHIP:DMG: Data = 0, [1652388147.842345][3606:3611] CHIP:DMG: }, [1652388147.842399][3606:3611] CHIP:DMG: [1652388147.842440][3606:3611] CHIP:DMG: }, [1652388147.842500][3606:3611] CHIP:DMG: [1652388147.842536][3606:3611] CHIP:DMG: AttributeReportIB = [1652388147.842587][3606:3611] CHIP:DMG: { [1652388147.842629][3606:3611] CHIP:DMG: AttributeDataIB = [1652388147.842677][3606:3611] CHIP:DMG: { [1652388147.842726][3606:3611] CHIP:DMG: DataVersion = 0x882f3a4f, [1652388147.842774][3606:3611] CHIP:DMG: AttributePathIB = [1652388147.842824][3606:3611] CHIP:DMG: { [1652388147.842881][3606:3611] CHIP:DMG: Endpoint = 0x0, [1652388147.842935][3606:3611] CHIP:DMG: Cluster = 0x28, [1652388147.842989][3606:3611] CHIP:DMG: Attribute = 0x0000_0004, [1652388147.843040][3606:3611] CHIP:DMG: } [1652388147.843092][3606:3611] CHIP:DMG: [1652388147.843145][3606:3611] CHIP:DMG: Data = 32769, [1652388147.843196][3606:3611] CHIP:DMG: }, [1652388147.843250][3606:3611] CHIP:DMG: [1652388147.843291][3606:3611] CHIP:DMG: }, [1652388147.843350][3606:3611] CHIP:DMG: [1652388147.843386][3606:3611] CHIP:DMG: AttributeReportIB = [1652388147.843440][3606:3611] CHIP:DMG: { [1652388147.843482][3606:3611] CHIP:DMG: AttributeDataIB = [1652388147.843528][3606:3611] CHIP:DMG: { [1652388147.843577][3606:3611] CHIP:DMG: DataVersion = 0x882f3a4f, [1652388147.843626][3606:3611] CHIP:DMG: AttributePathIB = [1652388147.843675][3606:3611] CHIP:DMG: { [1652388147.843725][3606:3611] CHIP:DMG: Endpoint = 0x0, [1652388147.843779][3606:3611] CHIP:DMG: Cluster = 0x28, [1652388147.843833][3606:3611] CHIP:DMG: Attribute = 0x0000_0002, [1652388147.843885][3606:3611] CHIP:DMG: } [1652388147.843937][3606:3611] CHIP:DMG: [1652388147.843994][3606:3611] CHIP:DMG: Data = 65521, [1652388147.844044][3606:3611] CHIP:DMG: }, [1652388147.844096][3606:3611] CHIP:DMG: [1652388147.844137][3606:3611] CHIP:DMG: }, [1652388147.844195][3606:3611] CHIP:DMG: [1652388147.844231][3606:3611] CHIP:DMG: AttributeReportIB = [1652388147.844282][3606:3611] CHIP:DMG: { [1652388147.844324][3606:3611] CHIP:DMG: AttributeDataIB = [1652388147.844374][3606:3611] CHIP:DMG: { [1652388147.844423][3606:3611] CHIP:DMG: DataVersion = 0x29d0a28b, [1652388147.844472][3606:3611] CHIP:DMG: AttributePathIB = [1652388147.844521][3606:3611] CHIP:DMG: { [1652388147.844576][3606:3611] CHIP:DMG: Endpoint = 0x0, [1652388147.844630][3606:3611] CHIP:DMG: Cluster = 0x30, [1652388147.844685][3606:3611] CHIP:DMG: Attribute = 0x0000_0003, [1652388147.844738][3606:3611] CHIP:DMG: } [1652388147.844791][3606:3611] CHIP:DMG: [1652388147.844842][3606:3611] CHIP:DMG: Data = 0, [1652388147.844892][3606:3611] CHIP:DMG: }, [1652388147.845073][3606:3611] CHIP:DMG: [1652388147.845118][3606:3611] CHIP:DMG: }, [1652388147.845176][3606:3611] CHIP:DMG: [1652388147.845213][3606:3611] CHIP:DMG: AttributeReportIB = [1652388147.845264][3606:3611] CHIP:DMG: { [1652388147.845306][3606:3611] CHIP:DMG: AttributeDataIB = [1652388147.845354][3606:3611] CHIP:DMG: { [1652388147.845404][3606:3611] CHIP:DMG: DataVersion = 0x29d0a28b, [1652388147.845452][3606:3611] CHIP:DMG: AttributePathIB = [1652388147.845501][3606:3611] CHIP:DMG: { [1652388147.845552][3606:3611] CHIP:DMG: Endpoint = 0x0, [1652388147.845605][3606:3611] CHIP:DMG: Cluster = 0x30, [1652388147.845659][3606:3611] CHIP:DMG: Attribute = 0x0000_0002, [1652388147.845710][3606:3611] CHIP:DMG: } [1652388147.845763][3606:3611] CHIP:DMG: [1652388147.846729][3606:3611] CHIP:DMG: Data = 0, [1652388147.846784][3606:3611] CHIP:DMG: }, [1652388147.846833][3606:3611] CHIP:DMG: [1652388147.846870][3606:3611] CHIP:DMG: }, [1652388147.846925][3606:3611] CHIP:DMG: [1652388147.846956][3606:3611] CHIP:DMG: AttributeReportIB = [1652388147.846994][3606:3611] CHIP:DMG: { [1652388147.847022][3606:3611] CHIP:DMG: AttributeDataIB = [1652388147.847061][3606:3611] CHIP:DMG: { [1652388147.847103][3606:3611] CHIP:DMG: DataVersion = 0x29d0a28b, [1652388147.847144][3606:3611] CHIP:DMG: AttributePathIB = [1652388147.847187][3606:3611] CHIP:DMG: { [1652388147.847230][3606:3611] CHIP:DMG: Endpoint = 0x0, [1652388147.847272][3606:3611] CHIP:DMG: Cluster = 0x30, [1652388147.847308][3606:3611] CHIP:DMG: Attribute = 0x0000_0001, [1652388147.847347][3606:3611] CHIP:DMG: } [1652388147.847394][3606:3611] CHIP:DMG: [1652388147.847439][3606:3611] CHIP:DMG: Data = [1652388147.847487][3606:3611] CHIP:DMG: { [1652388147.847533][3606:3611] CHIP:DMG: 0x0 = 60, [1652388147.847584][3606:3611] CHIP:DMG: }, [1652388147.847629][3606:3611] CHIP:DMG: }, [1652388147.847676][3606:3611] CHIP:DMG: [1652388147.847710][3606:3611] CHIP:DMG: }, [1652388147.847759][3606:3611] CHIP:DMG: [1652388147.847789][3606:3611] CHIP:DMG: AttributeReportIB = [1652388147.847831][3606:3611] CHIP:DMG: { [1652388147.847864][3606:3611] CHIP:DMG: AttributeDataIB = [1652388147.847902][3606:3611] CHIP:DMG: { [1652388147.847943][3606:3611] CHIP:DMG: DataVersion = 0x29d0a28b, [1652388147.847982][3606:3611] CHIP:DMG: AttributePathIB = [1652388147.848022][3606:3611] CHIP:DMG: { [1652388147.848064][3606:3611] CHIP:DMG: Endpoint = 0x0, [1652388147.848108][3606:3611] CHIP:DMG: Cluster = 0x30, [1652388147.848153][3606:3611] CHIP:DMG: Attribute = 0x0000_0000, [1652388147.848198][3606:3611] CHIP:DMG: } [1652388147.848240][3606:3611] CHIP:DMG: [1652388147.848281][3606:3611] CHIP:DMG: Data = 0, [1652388147.848322][3606:3611] CHIP:DMG: }, [1652388147.848367][3606:3611] CHIP:DMG: [1652388147.848400][3606:3611] CHIP:DMG: }, [1652388147.848446][3606:3611] CHIP:DMG: [1652388147.848476][3606:3611] CHIP:DMG: AttributeReportIB = [1652388147.848518][3606:3611] CHIP:DMG: { [1652388147.848551][3606:3611] CHIP:DMG: AttributeDataIB = [1652388147.848593][3606:3611] CHIP:DMG: { [1652388147.848636][3606:3611] CHIP:DMG: DataVersion = 0x441007ae, [1652388147.848675][3606:3611] CHIP:DMG: AttributePathIB = [1652388147.848718][3606:3611] CHIP:DMG: { [1652388147.848760][3606:3611] CHIP:DMG: Endpoint = 0x0, [1652388147.848803][3606:3611] CHIP:DMG: Cluster = 0x31, [1652388147.848848][3606:3611] CHIP:DMG: Attribute = 0x0000_FFFC, [1652388147.848889][3606:3611] CHIP:DMG: } [1652388147.848935][3606:3611] CHIP:DMG: [1652388147.848976][3606:3611] CHIP:DMG: Data = 2, [1652388147.849017][3606:3611] CHIP:DMG: }, [1652388147.849059][3606:3611] CHIP:DMG: [1652388147.849091][3606:3611] CHIP:DMG: }, [1652388147.849131][3606:3611] CHIP:DMG: [1652388147.849160][3606:3611] CHIP:DMG: ], [1652388147.849234][3606:3611] CHIP:DMG: [1652388147.849265][3606:3611] CHIP:DMG: SuppressResponse = true, [1652388147.849298][3606:3611] CHIP:DMG: InteractionModelRevision = 1 [1652388147.849326][3606:3611] CHIP:DMG: } [1652388147.850341][3606:3611] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1652388147.850391][3606:3611] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' [1652388147.850421][3606:3611] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1652388147.850447][3606:3611] CHIP:CTL: Arming failsafe (60 seconds) [1652388147.850513][3606:3611] CHIP:DMG: ICR moving to [AddingComm] [1652388147.850553][3606:3611] CHIP:DMG: ICR moving to [AddedComma] [1652388147.850676][3606:3611] CHIP:IN: Prepared secure message 0xaaaaf27f8bc8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54984i with MessageCounter:4283993. [1652388147.850730][3606:3611] CHIP:IN: Sending encrypted msg 0xaaaaf27f8bc8 with MessageCounter:4283993 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB118 msec [1652388147.850943][3606:3611] CHIP:DMG: ICR moving to [CommandSen] [1652388147.850990][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1691224 on exchange 54983i [1652388147.851052][3606:3611] CHIP:IN: Prepared secure message 0xffff7bffd9e8 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54983i with MessageCounter:4283994. [1652388147.851096][3606:3611] CHIP:IN: Sending encrypted msg 0xffff7bffd9e8 with MessageCounter:4283994 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB119 msec [1652388147.851194][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1691224 on exchange 54983i [1652388147.855635][3606:3611] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:1691225 on exchange 54984i [1652388147.855696][3606:3611] CHIP:EM: Found matching exchange: 54984i, Delegate: 0xffff74004fa0 [1652388147.855745][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:4283993 from Retrans Table on exchange 54984i [1652388147.855775][3606:3611] CHIP:EM: Removed CHIP MessageCounter:4283993 from RetransTable on exchange 54984i [1652388147.855816][3606:3611] CHIP:DMG: ICR moving to [ResponseRe] [1652388147.855879][3606:3611] CHIP:DMG: InvokeResponseMessage = [1652388147.855909][3606:3611] CHIP:DMG: { [1652388147.855937][3606:3611] CHIP:DMG: suppressResponse = false, [1652388147.855974][3606:3611] CHIP:DMG: InvokeResponseIBs = [1652388147.856014][3606:3611] CHIP:DMG: [ [1652388147.856044][3606:3611] CHIP:DMG: InvokeResponseIB = [1652388147.856088][3606:3611] CHIP:DMG: { [1652388147.856123][3606:3611] CHIP:DMG: CommandDataIB = [1652388147.856163][3606:3611] CHIP:DMG: { [1652388147.856200][3606:3611] CHIP:DMG: CommandPathIB = [1652388147.856241][3606:3611] CHIP:DMG: { [1652388147.856284][3606:3611] CHIP:DMG: EndpointId = 0x0, [1652388147.856328][3606:3611] CHIP:DMG: ClusterId = 0x30, [1652388147.856372][3606:3611] CHIP:DMG: CommandId = 0x1, [1652388147.856418][3606:3611] CHIP:DMG: }, [1652388147.856461][3606:3611] CHIP:DMG: [1652388147.856498][3606:3611] CHIP:DMG: CommandData = [1652388147.856539][3606:3611] CHIP:DMG: { [1652388147.856586][3606:3611] CHIP:DMG: 0x0 = 0, [1652388147.856633][3606:3611] CHIP:DMG: 0x1 = "", [1652388147.856678][3606:3611] CHIP:DMG: }, [1652388147.856717][3606:3611] CHIP:DMG: }, [1652388147.856761][3606:3611] CHIP:DMG: [1652388147.856794][3606:3611] CHIP:DMG: }, [1652388147.856837][3606:3611] CHIP:DMG: [1652388147.856866][3606:3611] CHIP:DMG: ], [1652388147.856902][3606:3611] CHIP:DMG: [1652388147.856929][3606:3611] CHIP:DMG: InteractionModelRevision = 1 [1652388147.856954][3606:3611] CHIP:DMG: }, [1652388147.857027][3606:3611] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1652388147.857067][3606:3611] CHIP:CTL: Received ArmFailSafe response [1652388147.857098][3606:3611] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1652388147.857123][3606:3611] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1652388147.857149][3606:3611] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1652388147.857171][3606:3611] CHIP:CTL: Setting Regulatory Config [1652388147.857193][3606:3611] CHIP:CTL: Device does not support configurable regulatory location [1652388147.857260][3606:3611] CHIP:DMG: ICR moving to [AddingComm] [1652388147.857299][3606:3611] CHIP:DMG: ICR moving to [AddedComma] [1652388147.857400][3606:3611] CHIP:IN: Prepared secure message 0xaaaaf27f8bc8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54985i with MessageCounter:4283995. [1652388147.857463][3606:3611] CHIP:IN: Sending encrypted msg 0xaaaaf27f8bc8 with MessageCounter:4283995 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB11F msec [1652388147.857649][3606:3611] CHIP:DMG: ICR moving to [CommandSen] [1652388147.857716][3606:3611] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.857752][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1691225 on exchange 54984i [1652388147.857808][3606:3611] CHIP:IN: Prepared secure message 0xffff7bffd9e8 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54984i with MessageCounter:4283996. [1652388147.857849][3606:3611] CHIP:IN: Sending encrypted msg 0xffff7bffd9e8 with MessageCounter:4283996 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB11F msec [1652388147.857938][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1691225 on exchange 54984i [1652388147.863143][3606:3611] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:1691226 on exchange 54985i [1652388147.863187][3606:3611] CHIP:EM: Found matching exchange: 54985i, Delegate: 0xffff740050f0 [1652388147.863226][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:4283995 from Retrans Table on exchange 54985i [1652388147.863253][3606:3611] CHIP:EM: Removed CHIP MessageCounter:4283995 from RetransTable on exchange 54985i [1652388147.863289][3606:3611] CHIP:DMG: ICR moving to [ResponseRe] [1652388147.863339][3606:3611] CHIP:DMG: InvokeResponseMessage = [1652388147.863366][3606:3611] CHIP:DMG: { [1652388147.863391][3606:3611] CHIP:DMG: suppressResponse = false, [1652388147.863419][3606:3611] CHIP:DMG: InvokeResponseIBs = [1652388147.863453][3606:3611] CHIP:DMG: [ [1652388147.863480][3606:3611] CHIP:DMG: InvokeResponseIB = [1652388147.863521][3606:3611] CHIP:DMG: { [1652388147.863552][3606:3611] CHIP:DMG: CommandDataIB = [1652388147.863589][3606:3611] CHIP:DMG: { [1652388147.863623][3606:3611] CHIP:DMG: CommandPathIB = [1652388147.863660][3606:3611] CHIP:DMG: { [1652388147.863702][3606:3611] CHIP:DMG: EndpointId = 0x0, [1652388147.863743][3606:3611] CHIP:DMG: ClusterId = 0x30, [1652388147.863784][3606:3611] CHIP:DMG: CommandId = 0x3, [1652388147.863822][3606:3611] CHIP:DMG: }, [1652388147.863862][3606:3611] CHIP:DMG: [1652388147.863896][3606:3611] CHIP:DMG: CommandData = [1652388147.863933][3606:3611] CHIP:DMG: { [1652388147.863976][3606:3611] CHIP:DMG: 0x0 = 0, [1652388147.864019][3606:3611] CHIP:DMG: 0x1 = "", [1652388147.864059][3606:3611] CHIP:DMG: }, [1652388147.864094][3606:3611] CHIP:DMG: }, [1652388147.864134][3606:3611] CHIP:DMG: [1652388147.864164][3606:3611] CHIP:DMG: }, [1652388147.864202][3606:3611] CHIP:DMG: [1652388147.864229][3606:3611] CHIP:DMG: ], [1652388147.864264][3606:3611] CHIP:DMG: [1652388147.864291][3606:3611] CHIP:DMG: InteractionModelRevision = 1 [1652388147.864317][3606:3611] CHIP:DMG: }, [1652388147.864388][3606:3611] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1652388147.864429][3606:3611] CHIP:CTL: Received SetRegulatoryConfig response [1652388147.864458][3606:3611] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1652388147.864482][3606:3611] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1652388147.864508][3606:3611] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1652388147.864530][3606:3611] CHIP:CTL: Sending request for PAI certificate [1652388147.864551][3606:3611] CHIP:CTL: Sending Certificate Chain request to 0xffff74001700 device [1652388147.864611][3606:3611] CHIP:DMG: ICR moving to [AddingComm] [1652388147.864662][3606:3611] CHIP:DMG: ICR moving to [AddedComma] [1652388147.864749][3606:3611] CHIP:IN: Prepared secure message 0xaaaaf27f8bc8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54986i with MessageCounter:4283997. [1652388147.864793][3606:3611] CHIP:IN: Sending encrypted msg 0xaaaaf27f8bc8 with MessageCounter:4283997 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB126 msec [1652388147.864960][3606:3611] CHIP:DMG: ICR moving to [CommandSen] [1652388147.865025][3606:3611] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.865060][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1691226 on exchange 54985i [1652388147.865113][3606:3611] CHIP:IN: Prepared secure message 0xffff7bffd9e8 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54985i with MessageCounter:4283998. [1652388147.865153][3606:3611] CHIP:IN: Sending encrypted msg 0xffff7bffd9e8 with MessageCounter:4283998 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB127 msec [1652388147.865240][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1691226 on exchange 54985i [1652388147.867481][3606:3611] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:1691227 on exchange 54986i [1652388147.867530][3606:3611] CHIP:EM: Found matching exchange: 54986i, Delegate: 0xffff74004fa0 [1652388147.867575][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:4283997 from Retrans Table on exchange 54986i [1652388147.867605][3606:3611] CHIP:EM: Removed CHIP MessageCounter:4283997 from RetransTable on exchange 54986i [1652388147.867645][3606:3611] CHIP:DMG: ICR moving to [ResponseRe] [1652388147.867701][3606:3611] CHIP:DMG: InvokeResponseMessage = [1652388147.867731][3606:3611] CHIP:DMG: { [1652388147.867759][3606:3611] CHIP:DMG: suppressResponse = false, [1652388147.867789][3606:3611] CHIP:DMG: InvokeResponseIBs = [1652388147.867827][3606:3611] CHIP:DMG: [ [1652388147.867857][3606:3611] CHIP:DMG: InvokeResponseIB = [1652388147.867901][3606:3611] CHIP:DMG: { [1652388147.867935][3606:3611] CHIP:DMG: CommandDataIB = [1652388147.867976][3606:3611] CHIP:DMG: { [1652388147.868013][3606:3611] CHIP:DMG: CommandPathIB = [1652388147.868055][3606:3611] CHIP:DMG: { [1652388147.868097][3606:3611] CHIP:DMG: EndpointId = 0x0, [1652388147.868142][3606:3611] CHIP:DMG: ClusterId = 0x3e, [1652388147.868188][3606:3611] CHIP:DMG: CommandId = 0x3, [1652388147.868229][3606:3611] CHIP:DMG: }, [1652388147.868272][3606:3611] CHIP:DMG: [1652388147.868309][3606:3611] CHIP:DMG: CommandData = [1652388147.868349][3606:3611] CHIP:DMG: { [1652388147.868393][3606:3611] CHIP:DMG: 0x0 = [ [1652388147.868436][3606:3611] CHIP:DMG: ... (byte string too long) ... [1652388147.868481][3606:3611] CHIP:DMG: ] [1652388147.868522][3606:3611] CHIP:DMG: }, [1652388147.868564][3606:3611] CHIP:DMG: }, [1652388147.868611][3606:3611] CHIP:DMG: [1652388147.868644][3606:3611] CHIP:DMG: }, [1652388147.868684][3606:3611] CHIP:DMG: [1652388147.868713][3606:3611] CHIP:DMG: ], [1652388147.868751][3606:3611] CHIP:DMG: [1652388147.868780][3606:3611] CHIP:DMG: InteractionModelRevision = 1 [1652388147.868809][3606:3611] CHIP:DMG: }, [1652388147.868885][3606:3611] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1652388147.868925][3606:3611] CHIP:CTL: Received certificate chain from the device [1652388147.868957][3606:3611] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest' [1652388147.868990][3606:3611] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' [1652388147.869019][3606:3611] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' [1652388147.869044][3606:3611] CHIP:CTL: Sending request for DAC certificate [1652388147.869066][3606:3611] CHIP:CTL: Sending Certificate Chain request to 0xffff74001700 device [1652388147.869131][3606:3611] CHIP:DMG: ICR moving to [AddingComm] [1652388147.869168][3606:3611] CHIP:DMG: ICR moving to [AddedComma] [1652388147.869263][3606:3611] CHIP:IN: Prepared secure message 0xaaaaf27f8bc8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54987i with MessageCounter:4283999. [1652388147.869311][3606:3611] CHIP:IN: Sending encrypted msg 0xaaaaf27f8bc8 with MessageCounter:4283999 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB12B msec [1652388147.869495][3606:3611] CHIP:DMG: ICR moving to [CommandSen] [1652388147.869562][3606:3611] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.869598][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1691227 on exchange 54986i [1652388147.869656][3606:3611] CHIP:IN: Prepared secure message 0xffff7bffd9e8 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54986i with MessageCounter:4284000. [1652388147.869698][3606:3611] CHIP:IN: Sending encrypted msg 0xffff7bffd9e8 with MessageCounter:4284000 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB12B msec [1652388147.869793][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1691227 on exchange 54986i [1652388147.871470][3606:3611] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:1691228 on exchange 54987i [1652388147.871515][3606:3611] CHIP:EM: Found matching exchange: 54987i, Delegate: 0xffff740050f0 [1652388147.871556][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:4283999 from Retrans Table on exchange 54987i [1652388147.871586][3606:3611] CHIP:EM: Removed CHIP MessageCounter:4283999 from RetransTable on exchange 54987i [1652388147.871624][3606:3611] CHIP:DMG: ICR moving to [ResponseRe] [1652388147.871678][3606:3611] CHIP:DMG: InvokeResponseMessage = [1652388147.871708][3606:3611] CHIP:DMG: { [1652388147.871736][3606:3611] CHIP:DMG: suppressResponse = false, [1652388147.871765][3606:3611] CHIP:DMG: InvokeResponseIBs = [1652388147.871803][3606:3611] CHIP:DMG: [ [1652388147.871833][3606:3611] CHIP:DMG: InvokeResponseIB = [1652388147.871876][3606:3611] CHIP:DMG: { [1652388147.871910][3606:3611] CHIP:DMG: CommandDataIB = [1652388147.871949][3606:3611] CHIP:DMG: { [1652388147.871986][3606:3611] CHIP:DMG: CommandPathIB = [1652388147.872027][3606:3611] CHIP:DMG: { [1652388147.872069][3606:3611] CHIP:DMG: EndpointId = 0x0, [1652388147.872117][3606:3611] CHIP:DMG: ClusterId = 0x3e, [1652388147.872160][3606:3611] CHIP:DMG: CommandId = 0x3, [1652388147.872200][3606:3611] CHIP:DMG: }, [1652388147.872245][3606:3611] CHIP:DMG: [1652388147.872282][3606:3611] CHIP:DMG: CommandData = [1652388147.872322][3606:3611] CHIP:DMG: { [1652388147.872363][3606:3611] CHIP:DMG: 0x0 = [ [1652388147.872403][3606:3611] CHIP:DMG: ... (byte string too long) ... [1652388147.872452][3606:3611] CHIP:DMG: ] [1652388147.872492][3606:3611] CHIP:DMG: }, [1652388147.872530][3606:3611] CHIP:DMG: }, [1652388147.872576][3606:3611] CHIP:DMG: [1652388147.872611][3606:3611] CHIP:DMG: }, [1652388147.872652][3606:3611] CHIP:DMG: [1652388147.872680][3606:3611] CHIP:DMG: ], [1652388147.872718][3606:3611] CHIP:DMG: [1652388147.872747][3606:3611] CHIP:DMG: InteractionModelRevision = 1 [1652388147.872775][3606:3611] CHIP:DMG: }, [1652388147.872851][3606:3611] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1652388147.872892][3606:3611] CHIP:CTL: Received certificate chain from the device [1652388147.872924][3606:3611] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest' [1652388147.872955][3606:3611] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' [1652388147.872983][3606:3611] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' [1652388147.873007][3606:3611] CHIP:CTL: Sending Attestation Request to the device. [1652388147.873031][3606:3611] CHIP:CTL: Sending Attestation request to 0xffff74001700 device [1652388147.873095][3606:3611] CHIP:DMG: ICR moving to [AddingComm] [1652388147.873134][3606:3611] CHIP:DMG: ICR moving to [AddedComma] [1652388147.873224][3606:3611] CHIP:IN: Prepared secure message 0xaaaaf27f8bc8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54988i with MessageCounter:4284001. [1652388147.873273][3606:3611] CHIP:IN: Sending encrypted msg 0xaaaaf27f8bc8 with MessageCounter:4284001 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB12F msec [1652388147.873447][3606:3611] CHIP:DMG: ICR moving to [CommandSen] [1652388147.873485][3606:3611] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1652388147.873538][3606:3611] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.873572][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1691228 on exchange 54987i [1652388147.873632][3606:3611] CHIP:IN: Prepared secure message 0xffff7bffd9e8 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54987i with MessageCounter:4284002. [1652388147.873676][3606:3611] CHIP:IN: Sending encrypted msg 0xffff7bffd9e8 with MessageCounter:4284002 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB12F msec [1652388147.873772][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1691228 on exchange 54987i [1652388147.878344][3606:3611] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:1691229 on exchange 54988i [1652388147.878388][3606:3611] CHIP:EM: Found matching exchange: 54988i, Delegate: 0xffff74004fa0 [1652388147.878431][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:4284001 from Retrans Table on exchange 54988i [1652388147.878460][3606:3611] CHIP:EM: Removed CHIP MessageCounter:4284001 from RetransTable on exchange 54988i [1652388147.878498][3606:3611] CHIP:DMG: ICR moving to [ResponseRe] [1652388147.878552][3606:3611] CHIP:DMG: InvokeResponseMessage = [1652388147.878582][3606:3611] CHIP:DMG: { [1652388147.878610][3606:3611] CHIP:DMG: suppressResponse = false, [1652388147.878640][3606:3611] CHIP:DMG: InvokeResponseIBs = [1652388147.878678][3606:3611] CHIP:DMG: [ [1652388147.878708][3606:3611] CHIP:DMG: InvokeResponseIB = [1652388147.878752][3606:3611] CHIP:DMG: { [1652388147.878784][3606:3611] CHIP:DMG: CommandDataIB = [1652388147.878824][3606:3611] CHIP:DMG: { [1652388147.878864][3606:3611] CHIP:DMG: CommandPathIB = [1652388147.878909][3606:3611] CHIP:DMG: { [1652388147.878955][3606:3611] CHIP:DMG: EndpointId = 0x0, [1652388147.878999][3606:3611] CHIP:DMG: ClusterId = 0x3e, [1652388147.879042][3606:3611] CHIP:DMG: CommandId = 0x1, [1652388147.879086][3606:3611] CHIP:DMG: }, [1652388147.879131][3606:3611] CHIP:DMG: [1652388147.879168][3606:3611] CHIP:DMG: CommandData = [1652388147.879209][3606:3611] CHIP:DMG: { [1652388147.879250][3606:3611] CHIP:DMG: 0x0 = [ [1652388147.879293][3606:3611] CHIP:DMG: ... (byte string too long) ... [1652388147.879338][3606:3611] CHIP:DMG: ] [1652388147.879382][3606:3611] CHIP:DMG: 0x1 = [ [1652388147.879441][3606:3611] CHIP:DMG: 0xa, 0x32, 0x6d, 0x1b, 0xe0, 0x79, 0x8f, 0xec, 0x41, 0xb5, 0xdf, 0x89, 0x47, 0x9f, 0x21, 0x29, 0x6c, 0xfe, 0xf0, 0xfe, 0x56, 0xeb, 0xd0, 0x29, 0xf3, 0x4c, 0x7d, 0x77, 0x25, 0x7d, 0x76, 0x3a, 0x69, 0xfb, 0x1f, 0xf7, 0xd4, 0x13, 0xe5, 0x4f, 0xd9, 0x2e [1652388147.879496][3606:3611] CHIP:DMG: ] [1652388147.879538][3606:3611] CHIP:DMG: }, [1652388147.879580][3606:3611] CHIP:DMG: }, [1652388147.879624][3606:3611] CHIP:DMG: [1652388147.879658][3606:3611] CHIP:DMG: }, [1652388147.879704][3606:3611] CHIP:DMG: [1652388147.879735][3606:3611] CHIP:DMG: ], [1652388147.879777][3606:3611] CHIP:DMG: [1652388147.879813][3606:3611] CHIP:DMG: InteractionModelRevision = 1 [1652388147.879845][3606:3611] CHIP:DMG: }, [1652388147.879930][3606:3611] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1652388147.879977][3606:3611] CHIP:CTL: Received Attestation Information from the device [1652388147.880012][3606:3611] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest' [1652388147.880090][3606:3611] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' [1652388147.880125][3606:3611] CHIP:CTL: Performing next commissioning step 'AttestationVerification' [1652388147.880151][3606:3611] CHIP:CTL: Verifying attestation [1652388147.887300][3606:3611] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1652388147.887370][3606:3611] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification' [1652388147.887401][3606:3611] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' [1652388147.887432][3606:3611] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' [1652388147.887461][3606:3611] CHIP:CTL: Sending CSR request to 0xffff74001700 device [1652388147.887550][3606:3611] CHIP:DMG: ICR moving to [AddingComm] [1652388147.887595][3606:3611] CHIP:DMG: ICR moving to [AddedComma] [1652388147.887729][3606:3611] CHIP:IN: Prepared secure message 0xaaaaf27f8bc8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54989i with MessageCounter:4284003. [1652388147.887789][3606:3611] CHIP:IN: Sending encrypted msg 0xaaaaf27f8bc8 with MessageCounter:4284003 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB13D msec [1652388147.888016][3606:3611] CHIP:DMG: ICR moving to [CommandSen] [1652388147.888062][3606:3611] CHIP:CTL: Sent CSR request, waiting for the CSR [1652388147.888133][3606:3611] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.888173][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1691229 on exchange 54988i [1652388147.888236][3606:3611] CHIP:IN: Prepared secure message 0xffff7bffd9e8 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54988i with MessageCounter:4284004. [1652388147.888284][3606:3611] CHIP:IN: Sending encrypted msg 0xffff7bffd9e8 with MessageCounter:4284004 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB13E msec [1652388147.888535][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1691229 on exchange 54988i [1652388147.893282][3606:3611] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:1691230 on exchange 54989i [1652388147.893322][3606:3611] CHIP:EM: Found matching exchange: 54989i, Delegate: 0xffff740050f0 [1652388147.893356][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:4284003 from Retrans Table on exchange 54989i [1652388147.893378][3606:3611] CHIP:EM: Removed CHIP MessageCounter:4284003 from RetransTable on exchange 54989i [1652388147.893408][3606:3611] CHIP:DMG: ICR moving to [ResponseRe] [1652388147.893455][3606:3611] CHIP:DMG: InvokeResponseMessage = [1652388147.893478][3606:3611] CHIP:DMG: { [1652388147.893499][3606:3611] CHIP:DMG: suppressResponse = false, [1652388147.893521][3606:3611] CHIP:DMG: InvokeResponseIBs = [1652388147.893550][3606:3611] CHIP:DMG: [ [1652388147.893572][3606:3611] CHIP:DMG: InvokeResponseIB = [1652388147.893610][3606:3611] CHIP:DMG: { [1652388147.893635][3606:3611] CHIP:DMG: CommandDataIB = [1652388147.893665][3606:3611] CHIP:DMG: { [1652388147.893694][3606:3611] CHIP:DMG: CommandPathIB = [1652388147.893727][3606:3611] CHIP:DMG: { [1652388147.893761][3606:3611] CHIP:DMG: EndpointId = 0x0, [1652388147.893797][3606:3611] CHIP:DMG: ClusterId = 0x3e, [1652388147.893829][3606:3611] CHIP:DMG: CommandId = 0x5, [1652388147.893860][3606:3611] CHIP:DMG: }, [1652388147.893892][3606:3611] CHIP:DMG: [1652388147.893922][3606:3611] CHIP:DMG: CommandData = [1652388147.893952][3606:3611] CHIP:DMG: { [1652388147.893985][3606:3611] CHIP:DMG: 0x0 = [ [1652388147.894036][3606:3611] CHIP:DMG: 0x15, 0x30, 0x1, 0xcc, 0x30, 0x81, 0xc9, 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 [1652388147.894075][3606:3611] CHIP:DMG: ] [1652388147.894125][3606:3611] CHIP:DMG: 0x1 = [ [1652388147.894173][3606:3611] CHIP:DMG: 0x1, 0xc1, 0x92, 0x78, 0xce, 0xd6, 0x11, 0x5b, 0xc3, 0x9, 0x92, 0xa2, 0x77, 0x1c, 0xe6, 0x6f, 0x29, 0xf1, 0x10, 0x57, 0x29, 0xc8, 0xd4, 0xcb, 0xdc, 0x93, 0xfc, 0x64, 0x52, 0x81, 0x2b, 0xf9, 0x43, 0x51, 0x4c, 0x11, 0x9e, 0xc3, 0x2e, 0x66, 0x6b, 0x43, [1652388147.894212][3606:3611] CHIP:DMG: ] [1652388147.894246][3606:3611] CHIP:DMG: }, [1652388147.894277][3606:3611] CHIP:DMG: }, [1652388147.894310][3606:3611] CHIP:DMG: [1652388147.894335][3606:3611] CHIP:DMG: }, [1652388147.894366][3606:3611] CHIP:DMG: [1652388147.894387][3606:3611] CHIP:DMG: ], [1652388147.894416][3606:3611] CHIP:DMG: [1652388147.894437][3606:3611] CHIP:DMG: InteractionModelRevision = 1 [1652388147.894458][3606:3611] CHIP:DMG: }, [1652388147.894520][3606:3611] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1652388147.894553][3606:3611] CHIP:CTL: Received certificate signing request from the device [1652388147.894579][3606:3611] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest' [1652388147.894600][3606:3611] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' [1652388147.894621][3606:3611] CHIP:CTL: Performing next commissioning step 'ValidateCSR' [1652388147.895680][3606:3611] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR' [1652388147.895723][3606:3611] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' [1652388147.895744][3606:3611] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' [1652388147.895764][3606:3611] CHIP:CTL: Getting certificate chain for the device from the issuer [1652388147.895961][3606:3611] CHIP:CTL: Verifying Certificate Signing Request [1652388147.896686][3606:3611] CHIP:CTL: Generating NOC [1652388147.896999][3606:3611] CHIP:CTL: Providing certificate chain to the commissioner [1652388147.897037][3606:3611] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../examples/chip-tool/third_party/connectedhomeip/src/controller/ExampleOperationalCredentialsIssuer.cpp:261: Success [1652388147.897064][3606:3611] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain' [1652388147.897226][3606:3611] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' [1652388147.897252][3606:3611] CHIP:CTL: Sending root certificate to the device [1652388147.897317][3606:3611] CHIP:DMG: ICR moving to [AddingComm] [1652388147.897347][3606:3611] CHIP:DMG: ICR moving to [AddedComma] [1652388147.897474][3606:3611] CHIP:IN: Prepared secure message 0xaaaaf27f8bc8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54990i with MessageCounter:4284005. [1652388147.897514][3606:3611] CHIP:IN: Sending encrypted msg 0xaaaaf27f8bc8 with MessageCounter:4284005 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB147 msec [1652388147.897681][3606:3611] CHIP:DMG: ICR moving to [CommandSen] [1652388147.897712][3606:3611] CHIP:CTL: Sent root certificate to the device [1652388147.897985][3606:3611] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.898025][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1691230 on exchange 54989i [1652388147.898078][3606:3611] CHIP:IN: Prepared secure message 0xffff7bffd9e8 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54989i with MessageCounter:4284006. [1652388147.898154][3606:3611] CHIP:IN: Sending encrypted msg 0xffff7bffd9e8 with MessageCounter:4284006 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB148 msec [1652388147.898251][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1691230 on exchange 54989i [1652388147.900433][3606:3611] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:1691231 on exchange 54990i [1652388147.900469][3606:3611] CHIP:EM: Found matching exchange: 54990i, Delegate: 0xffff74004fa0 [1652388147.900503][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:4284005 from Retrans Table on exchange 54990i [1652388147.900526][3606:3611] CHIP:EM: Removed CHIP MessageCounter:4284005 from RetransTable on exchange 54990i [1652388147.900555][3606:3611] CHIP:DMG: ICR moving to [ResponseRe] [1652388147.900600][3606:3611] CHIP:DMG: InvokeResponseMessage = [1652388147.900623][3606:3611] CHIP:DMG: { [1652388147.900644][3606:3611] CHIP:DMG: suppressResponse = false, [1652388147.900666][3606:3611] CHIP:DMG: InvokeResponseIBs = [1652388147.900695][3606:3611] CHIP:DMG: [ [1652388147.900716][3606:3611] CHIP:DMG: InvokeResponseIB = [1652388147.900749][3606:3611] CHIP:DMG: { [1652388147.900774][3606:3611] CHIP:DMG: CommandStatusIB = [1652388147.900803][3606:3611] CHIP:DMG: { [1652388147.900833][3606:3611] CHIP:DMG: CommandPathIB = [1652388147.900865][3606:3611] CHIP:DMG: { [1652388147.900896][3606:3611] CHIP:DMG: EndpointId = 0x0, [1652388147.900929][3606:3611] CHIP:DMG: ClusterId = 0x3e, [1652388147.900963][3606:3611] CHIP:DMG: CommandId = 0xb, [1652388147.900993][3606:3611] CHIP:DMG: }, [1652388147.901028][3606:3611] CHIP:DMG: [1652388147.901056][3606:3611] CHIP:DMG: StatusIB = [1652388147.901087][3606:3611] CHIP:DMG: { [1652388147.901119][3606:3611] CHIP:DMG: status = 0x00 (SUCCESS), [1652388147.901151][3606:3611] CHIP:DMG: }, [1652388147.901185][3606:3611] CHIP:DMG: [1652388147.901212][3606:3611] CHIP:DMG: }, [1652388147.901244][3606:3611] CHIP:DMG: [1652388147.901268][3606:3611] CHIP:DMG: }, [1652388147.901298][3606:3611] CHIP:DMG: [1652388147.901319][3606:3611] CHIP:DMG: ], [1652388147.901347][3606:3611] CHIP:DMG: [1652388147.901368][3606:3611] CHIP:DMG: InteractionModelRevision = 1 [1652388147.901390][3606:3611] CHIP:DMG: }, [1652388147.901446][3606:3611] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1652388147.901471][3606:3611] CHIP:CTL: Device confirmed that it has received the root certificate [1652388147.901494][3606:3611] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert' [1652388147.901513][3606:3611] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' [1652388147.901533][3606:3611] CHIP:CTL: Performing next commissioning step 'SendNOC' [1652388147.901596][3606:3611] CHIP:DMG: ICR moving to [AddingComm] [1652388147.901629][3606:3611] CHIP:DMG: ICR moving to [AddedComma] [1652388147.901728][3606:3611] CHIP:IN: Prepared secure message 0xaaaaf27f8bc8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 54991i with MessageCounter:4284007. [1652388147.901766][3606:3611] CHIP:IN: Sending encrypted msg 0xaaaaf27f8bc8 with MessageCounter:4284007 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB14B msec [1652388147.901947][3606:3611] CHIP:DMG: ICR moving to [CommandSen] [1652388147.901992][3606:3611] CHIP:CTL: Sent operational certificate to the device [1652388147.902051][3606:3611] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.902131][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1691231 on exchange 54990i [1652388147.902208][3606:3611] CHIP:IN: Prepared secure message 0xffff7bffd9e8 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54990i with MessageCounter:4284008. [1652388147.902258][3606:3611] CHIP:IN: Sending encrypted msg 0xffff7bffd9e8 with MessageCounter:4284008 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB14C msec [1652388147.902371][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1691231 on exchange 54990i [1652388148.014289][3606:3611] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:1691232 on exchange 54991i [1652388148.014385][3606:3611] CHIP:EM: Found matching exchange: 54991i, Delegate: 0xffff740050f0 [1652388148.014468][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:4284007 from Retrans Table on exchange 54991i [1652388148.014523][3606:3611] CHIP:EM: Removed CHIP MessageCounter:4284007 from RetransTable on exchange 54991i [1652388148.014594][3606:3611] CHIP:DMG: ICR moving to [ResponseRe] [1652388148.014695][3606:3611] CHIP:DMG: InvokeResponseMessage = [1652388148.014748][3606:3611] CHIP:DMG: { [1652388148.014805][3606:3611] CHIP:DMG: suppressResponse = false, [1652388148.014863][3606:3611] CHIP:DMG: InvokeResponseIBs = [1652388148.014935][3606:3611] CHIP:DMG: [ [1652388148.014987][3606:3611] CHIP:DMG: InvokeResponseIB = [1652388148.015062][3606:3611] CHIP:DMG: { [1652388148.015124][3606:3611] CHIP:DMG: CommandDataIB = [1652388148.015206][3606:3611] CHIP:DMG: { [1652388148.015280][3606:3611] CHIP:DMG: CommandPathIB = [1652388148.015358][3606:3611] CHIP:DMG: { [1652388148.015439][3606:3611] CHIP:DMG: EndpointId = 0x0, [1652388148.015540][3606:3611] CHIP:DMG: ClusterId = 0x3e, [1652388148.015625][3606:3611] CHIP:DMG: CommandId = 0x8, [1652388148.015703][3606:3611] CHIP:DMG: }, [1652388148.015786][3606:3611] CHIP:DMG: [1652388148.015858][3606:3611] CHIP:DMG: CommandData = [1652388148.015935][3606:3611] CHIP:DMG: { [1652388148.016016][3606:3611] CHIP:DMG: 0x0 = 0, [1652388148.016099][3606:3611] CHIP:DMG: 0x1 = 1, [1652388148.016180][3606:3611] CHIP:DMG: }, [1652388148.016252][3606:3611] CHIP:DMG: }, [1652388148.016335][3606:3611] CHIP:DMG: [1652388148.016399][3606:3611] CHIP:DMG: }, [1652388148.016478][3606:3611] CHIP:DMG: [1652388148.016532][3606:3611] CHIP:DMG: ], [1652388148.016602][3606:3611] CHIP:DMG: [1652388148.016655][3606:3611] CHIP:DMG: InteractionModelRevision = 1 [1652388148.016717][3606:3611] CHIP:DMG: }, [1652388148.016856][3606:3611] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1652388148.016932][3606:3611] CHIP:CTL: Device returned status 0 on receiving the NOC [1652388148.016979][3606:3611] CHIP:CTL: Operational credentials provisioned on device 0xffff74001700 [1652388148.017010][3606:3611] CHIP:TOO: Secure Pairing Success [1652388148.017040][3606:3611] CHIP:CTL: Successfully finished commissioning step 'SendNOC' [1652388148.017067][3606:3611] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'FindOperational' [1652388148.017095][3606:3611] CHIP:CTL: Performing next commissioning step 'FindOperational' [1652388148.017124][3606:3611] CHIP:CSM: FindOrEstablishSession: PeerId = 54076DAA023833D1:0000000000000001 [1652388148.017153][3606:3611] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1652388148.018206][3606:3611] CHIP:DIS: Operational node lookup already in progress. Will NOT start a new one. [1652388148.018298][3606:3611] CHIP:DMG: ICR moving to [AwaitingDe] [1652388148.018342][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1691232 on exchange 54991i [1652388148.018445][3606:3611] CHIP:IN: Prepared secure message 0xffff7bffd9e8 to 0xFFFFFFFB00000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54991i with MessageCounter:4284009. [1652388148.018496][3606:3611] CHIP:IN: Sending encrypted msg 0xffff7bffd9e8 with MessageCounter:4284009 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AB1C0 msec [1652388148.018630][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1691232 on exchange 54991i [1652388148.018928][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.018979][3606:3611] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388148.019009][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388148.019036][3606:3611] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388148.019590][3606:3611] CHIP:DIS: Lookup clearing interface for non LL address [1652388148.019629][3606:3611] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: new best score: 6 [1652388148.019717][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388148.019789][3606:3611] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388148.019821][3606:3611] CHIP:DIS: Checking node lookup status after 2 ms [1652388148.019847][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.020040][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.020076][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.020107][3606:3611] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388148.020135][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388148.020161][3606:3611] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388148.020604][3606:3611] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388148.020695][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388148.020764][3606:3611] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388148.020794][3606:3611] CHIP:DIS: Checking node lookup status after 3 ms [1652388148.020819][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.020942][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.020976][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.021006][3606:3611] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388148.021034][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388148.021060][3606:3611] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388148.021470][3606:3611] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388148.021549][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388148.021620][3606:3611] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388148.021649][3606:3611] CHIP:DIS: Checking node lookup status after 4 ms [1652388148.021674][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.021838][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.021871][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.021902][3606:3611] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388148.021930][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388148.021955][3606:3611] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388148.022415][3606:3611] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388148.022513][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388148.022583][3606:3611] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388148.022613][3606:3611] CHIP:DIS: Checking node lookup status after 5 ms [1652388148.022638][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.022894][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.022930][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.022961][3606:3611] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388148.022988][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388148.023014][3606:3611] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388148.023437][3606:3611] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388148.023521][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388148.023589][3606:3611] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388148.023618][3606:3611] CHIP:DIS: Checking node lookup status after 6 ms [1652388148.023643][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.023809][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.023843][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.023874][3606:3611] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388148.023901][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388148.023927][3606:3611] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388148.024339][3606:3611] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388148.024424][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388148.024492][3606:3611] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388148.024523][3606:3611] CHIP:DIS: Checking node lookup status after 7 ms [1652388148.024547][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.024985][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.025021][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.025052][3606:3611] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388148.025079][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388148.025105][3606:3611] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388148.025517][3606:3611] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388148.025726][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388148.025797][3606:3611] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388148.025828][3606:3611] CHIP:DIS: Checking node lookup status after 8 ms [1652388148.025853][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.026022][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.026056][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.026112][3606:3611] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388148.026143][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388148.026169][3606:3611] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388148.026603][3606:3611] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388148.026689][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388148.026757][3606:3611] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388148.026787][3606:3611] CHIP:DIS: Checking node lookup status after 9 ms [1652388148.026812][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.027183][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.027267][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.027291][3606:3611] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388148.027312][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388148.027331][3606:3611] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388148.027668][3606:3611] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388148.027741][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388148.027793][3606:3611] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388148.027815][3606:3611] CHIP:DIS: Checking node lookup status after 10 ms [1652388148.027834][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.028125][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.028153][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.028176][3606:3611] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388148.028196][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388148.028215][3606:3611] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388148.028543][3606:3611] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388148.028606][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388148.028657][3606:3611] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388148.028680][3606:3611] CHIP:DIS: Checking node lookup status after 11 ms [1652388148.028698][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.028827][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.028855][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.028878][3606:3611] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388148.028903][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388148.028923][3606:3611] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388148.029252][3606:3611] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388148.029316][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388148.029368][3606:3611] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388148.029390][3606:3611] CHIP:DIS: Checking node lookup status after 12 ms [1652388148.029409][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.029663][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.029691][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.029714][3606:3611] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388148.029734][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388148.029753][3606:3611] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388148.030066][3606:3611] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388148.030168][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388148.030222][3606:3611] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388148.030245][3606:3611] CHIP:DIS: Checking node lookup status after 13 ms [1652388148.030264][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.031837][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.031866][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.031889][3606:3611] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388148.031910][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388148.031929][3606:3611] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388148.032261][3606:3611] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388148.032324][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388148.032377][3606:3611] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388148.032399][3606:3611] CHIP:DIS: Checking node lookup status after 15 ms [1652388148.032418][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.033448][3606:3611] CHIP:DIS: Discovered node without a pending query [1652388148.033474][3606:3611] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388148.033497][3606:3611] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388148.033517][3606:3611] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388148.033536][3606:3611] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388148.033854][3606:3611] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388148.033915][3606:3611] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388148.033965][3606:3611] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388148.033987][3606:3611] CHIP:DIS: Checking node lookup status after 16 ms [1652388148.034005][3606:3611] CHIP:DIS: Keeping DNSSD lookup active [1652388148.218295][3606:3611] CHIP:DIS: Checking node lookup status after 201 ms [1652388148.218411][3606:3611] CHIP:CTL: Updating device address to UDP:[fd11:34::e65f:1ff:fe6a:faa0]:5540 while in state 1 [1652388148.218466][3606:3611] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000001]: State change 1 --> 2 [1652388148.218724][3606:3611] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1652388148.220264][3606:3611] CHIP:SC: Including MRP parameters [1652388148.220550][3606:3611] CHIP:IN: Prepared unauthenticated message 0xaaaaf27f8bc8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 54992i with MessageCounter:1864588019. [1652388148.220649][3606:3611] CHIP:IN: Sending unauthenticated msg 0xaaaaf27f8bc8 with MessageCounter:1864588019 to 0x0000000000000000 at monotonic time: 00000000013AB28A msec [1652388148.221014][3606:3611] CHIP:SC: Sent Sigma1 msg [1652388148.221111][3606:3611] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000001]: State change 2 --> 3 [1652388148.221171][3606:3611] CHIP:DIS: Discovery does not require any more timeouts [1652388148.234202][3606:3611] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:1378659135 on exchange 54992i [1652388148.234278][3606:3611] CHIP:EM: Found matching exchange: 54992i, Delegate: 0xffff7400aad0 [1652388148.234355][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:1864588019 from Retrans Table on exchange 54992i [1652388148.234412][3606:3611] CHIP:EM: Removed CHIP MessageCounter:1864588019 from RetransTable on exchange 54992i [1652388148.234483][3606:3611] CHIP:SC: Received Sigma2 msg [1652388148.234553][3606:3611] CHIP:SC: Peer assigned session session ID 31111 [1652388148.240502][3606:3611] CHIP:SC: Found MRP parameters in the message [1652388148.240585][3606:3611] CHIP:SC: Sending Sigma3 [1652388148.241124][3606:3611] CHIP:EM: Piggybacking Ack for MessageCounter:1378659135 on exchange: 54992i [1652388148.241210][3606:3611] CHIP:IN: Prepared unauthenticated message 0xaaaaf27f8bc8 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 54992i with MessageCounter:1864588020. [1652388148.241278][3606:3611] CHIP:IN: Sending unauthenticated msg 0xaaaaf27f8bc8 with MessageCounter:1864588020 to 0x0000000000000000 at monotonic time: 00000000013AB29F msec [1652388148.241589][3606:3611] CHIP:SC: Sent Sigma3 msg [1652388148.261598][3606:3611] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:1378659136 on exchange 54992i [1652388148.261651][3606:3611] CHIP:EM: Found matching exchange: 54992i, Delegate: 0xffff7400aad0 [1652388148.261699][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:1864588020 from Retrans Table on exchange 54992i [1652388148.261732][3606:3611] CHIP:EM: Removed CHIP MessageCounter:1864588020 from RetransTable on exchange 54992i [1652388148.261780][3606:3611] CHIP:SC: Success status report received. Session was established [1652388148.267386][3606:3611] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:8739 PSID:31111! [1652388148.267456][3606:3611] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000001]: State change 3 --> 4 [1652388148.267531][3606:3611] CHIP:CTL: Successfully finished commissioning step 'FindOperational' [1652388148.267570][3606:3611] CHIP:CTL: Commissioning stage next step: 'FindOperational' -> 'SendComplete' [1652388148.267605][3606:3611] CHIP:CTL: Performing next commissioning step 'SendComplete' [1652388148.267691][3606:3611] CHIP:DMG: ICR moving to [AddingComm] [1652388148.267736][3606:3611] CHIP:DMG: ICR moving to [AddedComma] [1652388148.267892][3606:3611] CHIP:IN: Prepared secure message 0xaaaaf27f8bc8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 54993i with MessageCounter:2080282. [1652388148.267956][3606:3611] CHIP:IN: Sending encrypted msg 0xaaaaf27f8bc8 with MessageCounter:2080282 to 0x0000000000000001 (1) at monotonic time: 00000000013AB2B9 msec [1652388148.268234][3606:3611] CHIP:DMG: ICR moving to [CommandSen] [1652388148.268295][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1378659136 on exchange 54992i [1652388148.268350][3606:3611] CHIP:IN: Prepared unauthenticated message 0xffff7bffd9d8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 54992i with MessageCounter:1864588021. [1652388148.268421][3606:3611] CHIP:IN: Sending unauthenticated msg 0xffff7bffd9d8 with MessageCounter:1864588021 to 0x0000000000000000 at monotonic time: 00000000013AB2BA msec [1652388148.268565][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1378659136 on exchange 54992i [1652388148.280052][3606:3611] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:1785609 on exchange 54993i [1652388148.280113][3606:3611] CHIP:EM: Found matching exchange: 54993i, Delegate: 0xffff740050f0 [1652388148.280166][3606:3611] CHIP:EM: Rxd Ack; Removing MessageCounter:2080282 from Retrans Table on exchange 54993i [1652388148.280203][3606:3611] CHIP:EM: Removed CHIP MessageCounter:2080282 from RetransTable on exchange 54993i [1652388148.280250][3606:3611] CHIP:DMG: ICR moving to [ResponseRe] [1652388148.280322][3606:3611] CHIP:DMG: InvokeResponseMessage = [1652388148.280359][3606:3611] CHIP:DMG: { [1652388148.280414][3606:3611] CHIP:DMG: suppressResponse = false, [1652388148.280455][3606:3611] CHIP:DMG: InvokeResponseIBs = [1652388148.280504][3606:3611] CHIP:DMG: [ [1652388148.280554][3606:3611] CHIP:DMG: InvokeResponseIB = [1652388148.280611][3606:3611] CHIP:DMG: { [1652388148.280653][3606:3611] CHIP:DMG: CommandDataIB = [1652388148.280715][3606:3611] CHIP:DMG: { [1652388148.280823][3606:3611] CHIP:DMG: CommandPathIB = [1652388148.280892][3606:3611] CHIP:DMG: { [1652388148.280950][3606:3611] CHIP:DMG: EndpointId = 0x0, [1652388148.281061][3606:3611] CHIP:DMG: ClusterId = 0x30, [1652388148.281141][3606:3611] CHIP:DMG: CommandId = 0x5, [1652388148.281205][3606:3611] CHIP:DMG: }, [1652388148.281279][3606:3611] CHIP:DMG: [1652388148.281375][3606:3611] CHIP:DMG: CommandData = [1652388148.281455][3606:3611] CHIP:DMG: { [1652388148.281515][3606:3611] CHIP:DMG: 0x0 = 0, [1652388148.281593][3606:3611] CHIP:DMG: 0x1 = "", [1652388148.281702][3606:3611] CHIP:DMG: }, [1652388148.281788][3606:3611] CHIP:DMG: }, [1652388148.281851][3606:3611] CHIP:DMG: [1652388148.281970][3606:3611] CHIP:DMG: }, [1652388148.282066][3606:3611] CHIP:DMG: [1652388148.282207][3606:3611] CHIP:DMG: ], [1652388148.282268][3606:3611] CHIP:DMG: [1652388148.282310][3606:3611] CHIP:DMG: InteractionModelRevision = 1 [1652388148.282368][3606:3611] CHIP:DMG: }, [1652388148.282476][3606:3611] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1652388148.282606][3606:3611] CHIP:CTL: Received CommissioningComplete response [1652388148.282671][3606:3611] CHIP:CTL: Successfully finished commissioning step 'SendComplete' [1652388148.282709][3606:3611] CHIP:CTL: Commissioning stage next step: 'SendComplete' -> 'Cleanup' [1652388148.282746][3606:3611] CHIP:CTL: Performing next commissioning step 'Cleanup' [1652388148.282885][3606:3611] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1652388148.282935][3606:3611] CHIP:TOO: Device commissioning completed with success [1652388148.283057][3606:3611] CHIP:DMG: ICR moving to [AwaitingDe] [1652388148.283112][3606:3611] CHIP:EM: Sending Standalone Ack for MessageCounter:1785609 on exchange 54993i [1652388148.283273][3606:3611] CHIP:IN: Prepared secure message 0xffff7bffd9e8 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 54993i with MessageCounter:2080283. [1652388148.283355][3606:3611] CHIP:IN: Sending encrypted msg 0xffff7bffd9e8 with MessageCounter:2080283 to 0x0000000000000001 (1) at monotonic time: 00000000013AB2C9 msec [1652388148.283614][3606:3611] CHIP:EM: Flushed pending ack for MessageCounter:1785609 on exchange 54993i [1652388148.283982][3606:3606] CHIP:CTL: Shutting down the commissioner [1652388148.284161][3606:3606] CHIP:CTL: Shutting down the controller [1652388148.284217][3606:3606] CHIP:CTL: Shutting down the commissioner [1652388148.284339][3606:3606] CHIP:CTL: Shutting down the controller [1652388148.284392][3606:3606] CHIP:IN: Expiring all connections for fabric 1!! [1652388148.284470][3606:3606] CHIP:CTL: Shutting down the commissioner [1652388148.284594][3606:3606] CHIP:CTL: Shutting down the controller [1652388148.284633][3606:3606] CHIP:IN: Expiring all connections for fabric 2!! [1652388148.284691][3606:3606] CHIP:CTL: Shutting down the commissioner [1652388148.284812][3606:3606] CHIP:CTL: Shutting down the controller [1652388148.284852][3606:3606] CHIP:IN: Expiring all connections for fabric 3!! [1652388148.284902][3606:3606] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1652388148.285573][3606:3606] CHIP:DMG: IM WH moving to [Uninitialized] [1652388148.285629][3606:3606] CHIP:DMG: IM WH moving to [Uninitialized] [1652388148.285666][3606:3606] CHIP:DMG: IM WH moving to [Uninitialized] [1652388148.285698][3606:3606] CHIP:DMG: IM WH moving to [Uninitialized] [1652388148.285734][3606:3606] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388148.285858][3606:3606] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1652388148.286238][3606:3606] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-BiXrxT) [1652388148.287085][3606:3606] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388148.287171][3606:3606] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1652388148.287213][3606:3606] CHIP:DL: Inet Layer shutdown [1652388148.287248][3606:3606] CHIP:DL: BLE shutdown [1652388148.287283][3606:3606] CHIP:DL: System Layer shutdown pi@ubuntu:~$ ./chip-tool accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects": [112233], "targets": null}, {"fabricIndex": 1, "privilege": 3, "authMode": 2, "subjects": null, "targets": null}]' 1 0 [1652388152.062484][3612:3612] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1652388152.062988][3612:3612] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1652388152.063170][3612:3612] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1652388152.063281][3612:3612] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1652388152.063675][3612:3612] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-gEaugk) [1652388152.064229][3612:3612] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388152.064282][3612:3612] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2) [1652388152.064902][3612:3612] CHIP:DL: Got Ethernet interface: eth0 [1652388152.065262][3612:3612] CHIP:DL: Found the primary Ethernet interface:eth0 [1652388152.065666][3612:3612] CHIP:DL: Got WiFi interface: wlan0 [1652388152.067511][3612:3612] CHIP:DL: Found the primary WiFi interface:wlan0 [1652388152.067616][3612:3612] CHIP:IN: UDP::Init bind&listen port=0 [1652388152.067747][3612:3612] CHIP:IN: UDP::Init bound to port=58808 [1652388152.067776][3612:3612] CHIP:IN: UDP::Init bind&listen port=0 [1652388152.067890][3612:3612] CHIP:IN: UDP::Init bound to port=40729 [1652388152.067929][3612:3612] CHIP:IN: BLEBase::Init - setting/overriding transport [1652388152.067952][3612:3612] CHIP:IN: TransportMgr initialized [1652388152.067988][3612:3612] CHIP:DIS: Init fabric pairing table with server storage [1652388152.068156][3612:3612] CHIP:IN: Loading from storage for fabric index 0x1 [1652388152.070980][3612:3612] CHIP:IN: Loading from storage for fabric index 0x2 [1652388152.071717][3612:3612] CHIP:IN: Loading from storage for fabric index 0x3 [1652388152.072420][3612:3612] CHIP:DIS: Add fabric pairing table delegate [1652388152.075262][3612:3612] CHIP:ZCL: Using ZAP configuration... [1652388152.077931][3612:3612] CHIP:DL: MDNS failed to join multicast group on wpan0 for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1652388152.078965][3612:3612] CHIP:CTL: System State Initialized... [1652388152.079040][3612:3612] CHIP:CTL: Setting attestation nonce to random value [1652388152.079106][3612:3612] CHIP:CTL: Setting CSR nonce to random value [1652388152.079198][3612:3612] CHIP:IN: UDP::Init bind&listen port=5550 [1652388152.079286][3612:3612] CHIP:IN: UDP::Init bound to port=5550 [1652388152.079323][3612:3612] CHIP:IN: UDP::Init bind&listen port=5550 [1652388152.079407][3612:3612] CHIP:IN: UDP::Init bound to port=5550 [1652388152.079431][3612:3612] CHIP:IN: TransportMgr initialized [1652388152.079563][3612:3612] CHIP:CTL: Setting attestation nonce to random value [1652388152.079655][3612:3612] CHIP:CTL: Setting CSR nonce to random value [1652388152.080695][3612:3612] CHIP:CTL: Generating NOC [1652388152.081657][3612:3612] CHIP:DIS: Verifying the received credentials [1652388152.083631][3612:3612] CHIP:DIS: Added new fabric at index: 0x1, Initialized: 1 [1652388152.083675][3612:3612] CHIP:DIS: Assigned compressed fabric ID: 0x54076DAA023833D1, node ID: 0x000000000001B669 [1652388152.083699][3612:3612] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x54076DAA023833D1 [1652388152.083742][3612:3612] CHIP:IN: UDP::Init bind&listen port=5550 [1652388152.083859][3612:3612] CHIP:IN: UDP::Init bound to port=5550 [1652388152.083886][3612:3612] CHIP:IN: UDP::Init bind&listen port=5550 [1652388152.083980][3612:3612] CHIP:IN: UDP::Init bound to port=5550 [1652388152.084004][3612:3612] CHIP:IN: TransportMgr initialized [1652388152.084105][3612:3612] CHIP:CTL: Setting attestation nonce to random value [1652388152.084176][3612:3612] CHIP:CTL: Setting CSR nonce to random value [1652388152.085175][3612:3612] CHIP:CTL: Generating NOC [1652388152.086333][3612:3612] CHIP:DIS: Verifying the received credentials [1652388152.088173][3612:3612] CHIP:DIS: Added new fabric at index: 0x2, Initialized: 1 [1652388152.088211][3612:3612] CHIP:DIS: Assigned compressed fabric ID: 0xBA72F338CA9489BB, node ID: 0x000000000001B669 [1652388152.088233][3612:3612] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xBA72F338CA9489BB [1652388152.088274][3612:3612] CHIP:IN: UDP::Init bind&listen port=5550 [1652388152.088389][3612:3612] CHIP:IN: UDP::Init bound to port=5550 [1652388152.088429][3612:3612] CHIP:IN: UDP::Init bind&listen port=5550 [1652388152.088514][3612:3612] CHIP:IN: UDP::Init bound to port=5550 [1652388152.088537][3612:3612] CHIP:IN: TransportMgr initialized [1652388152.088635][3612:3612] CHIP:CTL: Setting attestation nonce to random value [1652388152.088702][3612:3612] CHIP:CTL: Setting CSR nonce to random value [1652388152.089633][3612:3612] CHIP:CTL: Generating NOC [1652388152.090899][3612:3612] CHIP:DIS: Verifying the received credentials [1652388152.092829][3612:3612] CHIP:DIS: Added new fabric at index: 0x3, Initialized: 1 [1652388152.092880][3612:3612] CHIP:DIS: Assigned compressed fabric ID: 0x682D29C2E3920DF2, node ID: 0x000000000001B669 [1652388152.092900][3612:3612] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x682D29C2E3920DF2 [1652388152.092944][3612:3612] CHIP:IN: UDP::Init bind&listen port=5550 [1652388152.093063][3612:3612] CHIP:IN: UDP::Init bound to port=5550 [1652388152.093088][3612:3612] CHIP:IN: UDP::Init bind&listen port=5550 [1652388152.093164][3612:3612] CHIP:IN: UDP::Init bound to port=5550 [1652388152.093206][3612:3612] CHIP:IN: TransportMgr initialized [1652388152.127381][3612:3617] CHIP:DL: CHIP task running [1652388152.127536][3612:3617] CHIP:TOO: Sending command to node 0x1 [1652388152.127580][3612:3617] CHIP:CSM: FindOrEstablishSession: PeerId = 54076DAA023833D1:0000000000000001 [1652388152.127608][3612:3617] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1652388152.131883][3612:3617] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388152.131940][3612:3617] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388152.131964][3612:3617] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388152.131986][3612:3617] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388152.132481][3612:3617] CHIP:DIS: Lookup clearing interface for non LL address [1652388152.132517][3612:3617] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: new best score: 6 [1652388152.132588][3612:3617] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388152.132645][3612:3617] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388152.132670][3612:3617] CHIP:DIS: Checking node lookup status after 5 ms [1652388152.132692][3612:3617] CHIP:DIS: Keeping DNSSD lookup active [1652388152.132867][3612:3617] CHIP:DIS: Discovered node without a pending query [1652388152.132896][3612:3617] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388152.132918][3612:3617] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388152.132942][3612:3617] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388152.132963][3612:3617] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388152.133318][3612:3617] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388152.133387][3612:3617] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388152.133442][3612:3617] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388152.133465][3612:3617] CHIP:DIS: Checking node lookup status after 6 ms [1652388152.133485][3612:3617] CHIP:DIS: Keeping DNSSD lookup active [1652388152.135195][3612:3617] CHIP:DIS: Discovered node without a pending query [1652388152.135225][3612:3617] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388152.135250][3612:3617] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388152.135272][3612:3617] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388152.135293][3612:3617] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388152.135652][3612:3617] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388152.135725][3612:3617] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388152.135781][3612:3617] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388152.135805][3612:3617] CHIP:DIS: Checking node lookup status after 8 ms [1652388152.135826][3612:3617] CHIP:DIS: Keeping DNSSD lookup active [1652388152.138666][3612:3617] CHIP:DIS: Discovered node without a pending query [1652388152.138697][3612:3617] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388152.138723][3612:3617] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388152.138745][3612:3617] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388152.138767][3612:3617] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388152.139130][3612:3617] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388152.139203][3612:3617] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388152.139257][3612:3617] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388152.139281][3612:3617] CHIP:DIS: Checking node lookup status after 12 ms [1652388152.139301][3612:3617] CHIP:DIS: Keeping DNSSD lookup active [1652388152.139452][3612:3617] CHIP:DIS: Discovered node without a pending query [1652388152.139479][3612:3617] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388152.139503][3612:3617] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388152.139525][3612:3617] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388152.139545][3612:3617] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388152.139940][3612:3617] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388152.140024][3612:3617] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388152.140093][3612:3617] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388152.140122][3612:3617] CHIP:DIS: Checking node lookup status after 13 ms [1652388152.140148][3612:3617] CHIP:DIS: Keeping DNSSD lookup active [1652388152.141052][3612:3617] CHIP:DIS: Discovered node without a pending query [1652388152.141087][3612:3617] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388152.141117][3612:3617] CHIP:DIS: Addr 0: [fd11:33::e65f:1ff:fe6a:fa9f]:5540 [1652388152.141145][3612:3617] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:fa9f]:5540 [1652388152.141171][3612:3617] CHIP:DIS: Addr 2: [172.16.0.117]:5540 [1652388152.141590][3612:3617] CHIP:DIS: UDP:[fd11:33::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 6 [1652388152.141672][3612:3617] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:fa9f%eth0]:5540: score has not improved: 3 [1652388152.141740][3612:3617] CHIP:DIS: UDP:172.16.0.117%eth0:5540: score has not improved: 2 [1652388152.141769][3612:3617] CHIP:DIS: Checking node lookup status after 14 ms [1652388152.141795][3612:3617] CHIP:DIS: Keeping DNSSD lookup active [1652388152.225409][3612:3617] CHIP:DIS: Discovered node without a pending query [1652388152.225482][3612:3617] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388152.225536][3612:3617] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388152.225582][3612:3617] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388152.225625][3612:3617] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388152.226423][3612:3617] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388152.226564][3612:3617] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388152.226676][3612:3617] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388152.226724][3612:3617] CHIP:DIS: Checking node lookup status after 99 ms [1652388152.226765][3612:3617] CHIP:DIS: Keeping DNSSD lookup active [1652388152.227576][3612:3617] CHIP:DIS: Discovered node without a pending query [1652388152.227632][3612:3617] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388152.227681][3612:3617] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388152.227725][3612:3617] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388152.227767][3612:3617] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388152.228426][3612:3617] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388152.228554][3612:3617] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388152.228697][3612:3617] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388152.228751][3612:3617] CHIP:DIS: Checking node lookup status after 101 ms [1652388152.228794][3612:3617] CHIP:DIS: Keeping DNSSD lookup active [1652388152.230144][3612:3617] CHIP:DIS: Discovered node without a pending query [1652388152.230206][3612:3617] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388152.230258][3612:3617] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388152.230302][3612:3617] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388152.230344][3612:3617] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388152.231017][3612:3617] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388152.231151][3612:3617] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388152.231259][3612:3617] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388152.231305][3612:3617] CHIP:DIS: Checking node lookup status after 104 ms [1652388152.231346][3612:3617] CHIP:DIS: Keeping DNSSD lookup active [1652388152.232680][3612:3617] CHIP:DIS: Discovered node without a pending query [1652388152.232735][3612:3617] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000001 [1652388152.232784][3612:3617] CHIP:DIS: Addr 0: [fd11:34::e65f:1ff:fe6a:faa0]:5540 [1652388152.232828][3612:3617] CHIP:DIS: Addr 1: [fe80::e65f:1ff:fe6a:faa0]:5540 [1652388152.232870][3612:3617] CHIP:DIS: Addr 2: [192.168.162.33]:5540 [1652388152.233522][3612:3617] CHIP:DIS: UDP:[fd11:34::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 6 [1652388152.233657][3612:3617] CHIP:DIS: UDP:[fe80::e65f:1ff:fe6a:faa0%wlan0]:5540: score has not improved: 3 [1652388152.233767][3612:3617] CHIP:DIS: UDP:192.168.162.33%wlan0:5540: score has not improved: 2 [1652388152.233809][3612:3617] CHIP:DIS: Checking node lookup status after 106 ms [1652388152.233838][3612:3617] CHIP:DIS: Keeping DNSSD lookup active [1652388152.328178][3612:3617] CHIP:DIS: Checking node lookup status after 201 ms [1652388152.328276][3612:3617] CHIP:CTL: Updating device address to UDP:[fd11:33::e65f:1ff:fe6a:fa9f]:5540 while in state 1 [1652388152.328328][3612:3617] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000001]: State change 1 --> 2 [1652388152.328704][3612:3617] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1652388152.330060][3612:3617] CHIP:SC: Including MRP parameters [1652388152.330552][3612:3617] CHIP:IN: Prepared unauthenticated message 0xaaaacb7ced78 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 1770i with MessageCounter:1736088650. [1652388152.330652][3612:3617] CHIP:IN: Sending unauthenticated msg 0xaaaacb7ced78 with MessageCounter:1736088650 to 0x0000000000000000 at monotonic time: 00000000013AC298 msec [1652388152.330957][3612:3617] CHIP:SC: Sent Sigma1 msg [1652388152.331024][3612:3617] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000001]: State change 2 --> 3 [1652388152.331085][3612:3617] CHIP:DIS: Discovery does not require any more timeouts [1652388152.333834][3612:3617] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:1378659137 on exchange 1770i [1652388152.333908][3612:3617] CHIP:EM: Found matching exchange: 1770i, Delegate: 0xffffa00015d0 [1652388152.333985][3612:3617] CHIP:EM: Rxd Ack; Removing MessageCounter:1736088650 from Retrans Table on exchange 1770i [1652388152.334041][3612:3617] CHIP:EM: Removed CHIP MessageCounter:1736088650 from RetransTable on exchange 1770i [1652388152.334159][3612:3617] CHIP:SC: Received Sigma2Resume msg [1652388152.334320][3612:3617] CHIP:SC: Found MRP parameters in the message [1652388152.334383][3612:3617] CHIP:SC: Peer assigned session session ID 31112 [1652388152.340797][3612:3617] CHIP:SC: Sending status report. Protocol code 0, exchange 1770 [1652388152.340862][3612:3617] CHIP:EM: Piggybacking Ack for MessageCounter:1378659137 on exchange: 1770i [1652388152.340909][3612:3617] CHIP:IN: Prepared unauthenticated message 0xaaaacb7ced78 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 1770i with MessageCounter:1736088651. [1652388152.340959][3612:3617] CHIP:IN: Sending unauthenticated msg 0xaaaacb7ced78 with MessageCounter:1736088651 to 0x0000000000000000 at monotonic time: 00000000013AC2A2 msec [1652388152.341230][3612:3617] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:9662 PSID:31112! [1652388152.341274][3612:3617] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000001]: State change 3 --> 4 [1652388152.341326][3612:3617] CHIP:TOO: Sending WriteAttribute to cluster 0x0000_001F on endpoint 0 [1652388152.341407][3612:3617] CHIP:DMG: WriteClient moving to [AddAttribu] [1652388152.341457][3612:3617] CHIP:DMG: WriteClient moving to [AddAttribu] [1652388152.341489][3612:3617] CHIP:DMG: WriteClient moving to [AddAttribu] [1652388152.341591][3612:3617] CHIP:IN: Prepared secure message 0xaaaacb7ced98 to 0x0000000000000001 (1) of type 0x6 and protocolId (0, 1) on exchange 1771i with MessageCounter:4069524. [1652388152.341637][3612:3617] CHIP:IN: Sending encrypted msg 0xaaaacb7ced98 with MessageCounter:4069524 to 0x0000000000000001 (1) at monotonic time: 00000000013AC2A3 msec [1652388152.341804][3612:3617] CHIP:DMG: WriteClient moving to [AwaitingRe] [1652388152.350897][3612:3617] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:1378659138 on exchange 1770i [1652388152.350938][3612:3617] CHIP:EM: Found matching exchange: 1770i, Delegate: (nil) [1652388152.350982][3612:3617] CHIP:EM: Rxd Ack; Removing MessageCounter:1736088651 from Retrans Table on exchange 1770i [1652388152.351010][3612:3617] CHIP:EM: Removed CHIP MessageCounter:1736088651 from RetransTable on exchange 1770i [1652388152.635482][3612:3617] CHIP:EM: Received message of type 0x7 with protocolId (0, 1) and MessageCounter:11415748 on exchange 1771i [1652388152.635571][3612:3617] CHIP:EM: Found matching exchange: 1771i, Delegate: 0xffffa0004600 [1652388152.635650][3612:3617] CHIP:EM: Rxd Ack; Removing MessageCounter:4069524 from Retrans Table on exchange 1771i [1652388152.635706][3612:3617] CHIP:EM: Removed CHIP MessageCounter:4069524 from RetransTable on exchange 1771i [1652388152.635777][3612:3617] CHIP:DMG: WriteClient moving to [ResponseRe] [1652388152.635891][3612:3617] CHIP:DMG: WriteResponseMessage = [1652388152.635948][3612:3617] CHIP:DMG: { [1652388152.635997][3612:3617] CHIP:DMG: AttributeStatusIBs = [1652388152.636070][3612:3617] CHIP:DMG: [ [1652388152.636125][3612:3617] CHIP:DMG: AttributeStatusIB = [1652388152.636195][3612:3617] CHIP:DMG: { [1652388152.636254][3612:3617] CHIP:DMG: AttributePathIB = [1652388152.636331][3612:3617] CHIP:DMG: { [1652388152.636405][3612:3617] CHIP:DMG: Endpoint = 0x0, [1652388152.636484][3612:3617] CHIP:DMG: Cluster = 0x1f, [1652388152.636555][3612:3617] CHIP:DMG: Attribute = 0x0000_0000, [1652388152.636634][3612:3617] CHIP:DMG: } [1652388152.636724][3612:3617] CHIP:DMG: [1652388152.636787][3612:3617] CHIP:DMG: StatusIB = [1652388152.636860][3612:3617] CHIP:DMG: { [1652388152.636940][3612:3617] CHIP:DMG: status = 0x00 (SUCCESS), [1652388152.637005][3612:3617] CHIP:DMG: }, [1652388152.637064][3612:3617] CHIP:DMG: [1652388152.637120][3612:3617] CHIP:DMG: }, [1652388152.637208][3612:3617] CHIP:DMG: [1652388152.637263][3612:3617] CHIP:DMG: AttributeStatusIB = [1652388152.637328][3612:3617] CHIP:DMG: { [1652388152.637391][3612:3617] CHIP:DMG: AttributePathIB = [1652388152.637470][3612:3617] CHIP:DMG: { [1652388152.637541][3612:3617] CHIP:DMG: Endpoint = 0x0, [1652388152.637617][3612:3617] CHIP:DMG: Cluster = 0x1f, [1652388152.637700][3612:3617] CHIP:DMG: Attribute = 0x0000_0000, [1652388152.637783][3612:3617] CHIP:DMG: ListIndex = Null, [1652388152.637853][3612:3617] CHIP:DMG: } [1652388152.637929][3612:3617] CHIP:DMG: [1652388152.637994][3612:3617] CHIP:DMG: StatusIB = [1652388152.638064][3612:3617] CHIP:DMG: { [1652388152.638189][3612:3617] CHIP:DMG: status = 0x00 (SUCCESS), [1652388152.638254][3612:3617] CHIP:DMG: }, [1652388152.638336][3612:3617] CHIP:DMG: [1652388152.638393][3612:3617] CHIP:DMG: }, [1652388152.638478][3612:3617] CHIP:DMG: [1652388152.638533][3612:3617] CHIP:DMG: AttributeStatusIB = [1652388152.638597][3612:3617] CHIP:DMG: { [1652388152.638659][3612:3617] CHIP:DMG: AttributePathIB = [1652388152.638734][3612:3617] CHIP:DMG: { [1652388152.638802][3612:3617] CHIP:DMG: Endpoint = 0x0, [1652388152.638877][3612:3617] CHIP:DMG: Cluster = 0x1f, [1652388152.638960][3612:3617] CHIP:DMG: Attribute = 0x0000_0000, [1652388152.639033][3612:3617] CHIP:DMG: ListIndex = Null, [1652388152.639110][3612:3617] CHIP:DMG: } [1652388152.639196][3612:3617] CHIP:DMG: [1652388152.639270][3612:3617] CHIP:DMG: StatusIB = [1652388152.639346][3612:3617] CHIP:DMG: { [1652388152.639409][3612:3617] CHIP:DMG: status = 0x00 (SUCCESS), [1652388152.639478][3612:3617] CHIP:DMG: }, [1652388152.639550][3612:3617] CHIP:DMG: [1652388152.639607][3612:3617] CHIP:DMG: }, [1652388152.639678][3612:3617] CHIP:DMG: [1652388152.639732][3612:3617] CHIP:DMG: ], [1652388152.639815][3612:3617] CHIP:DMG: [1652388152.639868][3612:3617] CHIP:DMG: InteractionModelRevision = 1 [1652388152.639920][3612:3617] CHIP:DMG: } [1652388152.640219][3612:3617] CHIP:DMG: WriteClient moving to [AwaitingDe] [1652388152.640321][3612:3617] CHIP:EM: Sending Standalone Ack for MessageCounter:11415748 on exchange 1771i [1652388152.640449][3612:3617] CHIP:IN: Prepared secure message 0xffffb2ffb9e8 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 1771i with MessageCounter:4069525. [1652388152.640532][3612:3617] CHIP:IN: Sending encrypted msg 0xffffb2ffb9e8 with MessageCounter:4069525 to 0x0000000000000001 (1) at monotonic time: 00000000013AC3CE msec [1652388152.640747][3612:3617] CHIP:EM: Flushed pending ack for MessageCounter:11415748 on exchange 1771i [1652388152.641107][3612:3612] CHIP:CTL: Shutting down the commissioner [1652388152.641482][3612:3612] CHIP:CTL: Shutting down the controller [1652388152.641639][3612:3612] CHIP:CTL: Shutting down the commissioner [1652388152.641803][3612:3612] CHIP:CTL: Shutting down the controller [1652388152.641870][3612:3612] CHIP:IN: Expiring all connections for fabric 1!! [1652388152.641990][3612:3612] CHIP:CTL: Shutting down the commissioner [1652388152.642242][3612:3612] CHIP:CTL: Shutting down the controller [1652388152.642301][3612:3612] CHIP:IN: Expiring all connections for fabric 2!! [1652388152.642379][3612:3612] CHIP:CTL: Shutting down the commissioner [1652388152.642567][3612:3612] CHIP:CTL: Shutting down the controller [1652388152.642621][3612:3612] CHIP:IN: Expiring all connections for fabric 3!! [1652388152.642771][3612:3612] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1652388152.643739][3612:3612] CHIP:DMG: IM WH moving to [Uninitialized] [1652388152.643799][3612:3612] CHIP:DMG: IM WH moving to [Uninitialized] [1652388152.643845][3612:3612] CHIP:DMG: IM WH moving to [Uninitialized] [1652388152.643889][3612:3612] CHIP:DMG: IM WH moving to [Uninitialized] [1652388152.643937][3612:3612] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388152.644092][3612:3612] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1652388152.644694][3612:3612] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-RnAiPj) [1652388152.648731][3612:3612] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388152.648801][3612:3612] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1652388152.648829][3612:3612] CHIP:DL: Inet Layer shutdown [1652388152.648853][3612:3612] CHIP:DL: BLE shutdown [1652388152.648878][3612:3612] CHIP:DL: System Layer shutdown pi@ubuntu:~$ ./chip-tool pairing ble-thread 2 hex:0e080000000000000000000300000b35060004001fffe00208dead00beef00cafe0708fddead00beef0000051013a407d183a0c84d019e1bdd2de8a5a4030a4f70656e5468726561640102d20a0410dc83d101d57ce62a0f3a46b77a7683900c0402a0fff8 20202021 3840 [1652388156.011934][3618:3618] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1652388156.012418][3618:3618] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1652388156.012713][3618:3618] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1652388156.012821][3618:3618] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1652388156.013224][3618:3618] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-lYw5EL) [1652388156.013772][3618:3618] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388156.013872][3618:3618] CHIP:DL: NVS set: chip-counters/reboot-count = 3 (0x3) [1652388156.014635][3618:3618] CHIP:DL: Got Ethernet interface: eth0 [1652388156.015021][3618:3618] CHIP:DL: Found the primary Ethernet interface:eth0 [1652388156.015400][3618:3618] CHIP:DL: Got WiFi interface: wlan0 [1652388156.021034][3618:3618] CHIP:DL: Found the primary WiFi interface:wlan0 [1652388156.021130][3618:3618] CHIP:IN: UDP::Init bind&listen port=0 [1652388156.021251][3618:3618] CHIP:IN: UDP::Init bound to port=53499 [1652388156.021291][3618:3618] CHIP:IN: UDP::Init bind&listen port=0 [1652388156.021392][3618:3618] CHIP:IN: UDP::Init bound to port=34810 [1652388156.021417][3618:3618] CHIP:IN: BLEBase::Init - setting/overriding transport [1652388156.021438][3618:3618] CHIP:IN: TransportMgr initialized [1652388156.021483][3618:3618] CHIP:DIS: Init fabric pairing table with server storage [1652388156.021630][3618:3618] CHIP:IN: Loading from storage for fabric index 0x1 [1652388156.024322][3618:3618] CHIP:IN: Loading from storage for fabric index 0x2 [1652388156.025151][3618:3618] CHIP:IN: Loading from storage for fabric index 0x3 [1652388156.025776][3618:3618] CHIP:DIS: Add fabric pairing table delegate [1652388156.029225][3618:3618] CHIP:ZCL: Using ZAP configuration... [1652388156.032385][3618:3618] CHIP:DL: MDNS failed to join multicast group on wpan0 for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1652388156.033653][3618:3618] CHIP:CTL: System State Initialized... [1652388156.033736][3618:3618] CHIP:CTL: Setting attestation nonce to random value [1652388156.033814][3618:3618] CHIP:CTL: Setting CSR nonce to random value [1652388156.033925][3618:3618] CHIP:IN: UDP::Init bind&listen port=5550 [1652388156.034041][3618:3618] CHIP:IN: UDP::Init bound to port=5550 [1652388156.034075][3618:3618] CHIP:IN: UDP::Init bind&listen port=5550 [1652388156.034221][3618:3618] CHIP:IN: UDP::Init bound to port=5550 [1652388156.034252][3618:3618] CHIP:IN: TransportMgr initialized [1652388156.034348][3618:3618] CHIP:CTL: Setting attestation nonce to random value [1652388156.034427][3618:3618] CHIP:CTL: Setting CSR nonce to random value [1652388156.035805][3618:3618] CHIP:CTL: Generating NOC [1652388156.036778][3618:3618] CHIP:DIS: Verifying the received credentials [1652388156.038663][3618:3618] CHIP:DIS: Added new fabric at index: 0x1, Initialized: 1 [1652388156.038707][3618:3618] CHIP:DIS: Assigned compressed fabric ID: 0x54076DAA023833D1, node ID: 0x000000000001B669 [1652388156.038729][3618:3618] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x54076DAA023833D1 [1652388156.038772][3618:3618] CHIP:IN: UDP::Init bind&listen port=5550 [1652388156.038883][3618:3618] CHIP:IN: UDP::Init bound to port=5550 [1652388156.038924][3618:3618] CHIP:IN: UDP::Init bind&listen port=5550 [1652388156.039012][3618:3618] CHIP:IN: UDP::Init bound to port=5550 [1652388156.039035][3618:3618] CHIP:IN: TransportMgr initialized [1652388156.039140][3618:3618] CHIP:CTL: Setting attestation nonce to random value [1652388156.039226][3618:3618] CHIP:CTL: Setting CSR nonce to random value [1652388156.040164][3618:3618] CHIP:CTL: Generating NOC [1652388156.041054][3618:3618] CHIP:DIS: Verifying the received credentials [1652388156.043112][3618:3618] CHIP:DIS: Added new fabric at index: 0x2, Initialized: 1 [1652388156.043161][3618:3618] CHIP:DIS: Assigned compressed fabric ID: 0xBA72F338CA9489BB, node ID: 0x000000000001B669 [1652388156.043184][3618:3618] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xBA72F338CA9489BB [1652388156.043232][3618:3618] CHIP:IN: UDP::Init bind&listen port=5550 [1652388156.043358][3618:3618] CHIP:IN: UDP::Init bound to port=5550 [1652388156.043392][3618:3618] CHIP:IN: UDP::Init bind&listen port=5550 [1652388156.043470][3618:3618] CHIP:IN: UDP::Init bound to port=5550 [1652388156.043498][3618:3618] CHIP:IN: TransportMgr initialized [1652388156.043626][3618:3618] CHIP:CTL: Setting attestation nonce to random value [1652388156.043726][3618:3618] CHIP:CTL: Setting CSR nonce to random value [1652388156.044702][3618:3618] CHIP:CTL: Generating NOC [1652388156.045725][3618:3618] CHIP:DIS: Verifying the received credentials [1652388156.047573][3618:3618] CHIP:DIS: Added new fabric at index: 0x3, Initialized: 1 [1652388156.047615][3618:3618] CHIP:DIS: Assigned compressed fabric ID: 0x682D29C2E3920DF2, node ID: 0x000000000001B669 [1652388156.047635][3618:3618] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x682D29C2E3920DF2 [1652388156.047678][3618:3618] CHIP:IN: UDP::Init bind&listen port=5550 [1652388156.047796][3618:3618] CHIP:IN: UDP::Init bound to port=5550 [1652388156.047838][3618:3618] CHIP:IN: UDP::Init bind&listen port=5550 [1652388156.047928][3618:3618] CHIP:IN: UDP::Init bound to port=5550 [1652388156.047952][3618:3618] CHIP:IN: TransportMgr initialized [1652388156.083088][3618:3623] CHIP:DL: CHIP task running [1652388156.083485][3618:3623] CHIP:SC: Assigned local session key ID 36224 [1652388156.083560][3618:3623] CHIP:SC: Including MRP parameters in PBKDF param request [1652388156.083622][3618:3623] CHIP:IN: Prepared unauthenticated message 0xffff97ffdd48 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 48454i with MessageCounter:2791243022. [1652388156.083665][3618:3623] CHIP:IN: Sending unauthenticated msg 0xffff97ffdd48 with MessageCounter:2791243022 to 0x0000000000000000 at monotonic time: 00000000013AD141 msec [1652388156.083696][3618:3623] CHIP:IN: Message appended to BLE send queue [1652388156.083729][3618:3623] CHIP:SC: Sent PBKDF param request [1652388156.083756][3618:3623] CHIP:CTL: Setting thread operational dataset from parameters [1652388156.083778][3618:3623] CHIP:CTL: Setting attestation nonce to random value [1652388156.083823][3618:3623] CHIP:CTL: Setting CSR nonce to random value [1652388156.083866][3618:3623] CHIP:CTL: Commission called for node ID 0x0000000000000002 [1652388156.084099][3618:3624] CHIP:DL: TRACE: Bluez mainloop starting Thread [1652388156.084314][3618:3621] CHIP:DL: TRACE: Bus acquired for name C-0e22 [1652388156.091112][3618:3623] CHIP:DL: PlatformBlueZInit init success [1652388156.096517][3618:3621] CHIP:BLE: BLE removing known devices. [1652388156.098170][3618:3621] CHIP:BLE: BLE initiating scan. [1652388156.238575][3618:3621] CHIP:BLE: Device E2:70:EA:7A:B1:80 does not look like a CHIP device. [1652388156.249386][3618:3621] CHIP:BLE: Device 28:FF:3C:8D:13:E3 does not look like a CHIP device. [1652388156.251091][3618:3621] CHIP:BLE: Device 1C:2D:1A:ED:70:2E does not look like a CHIP device. [1652388156.268269][3618:3621] CHIP:BLE: Device E1:A1:52:5F:49:0D does not look like a CHIP device. [1652388156.270466][3618:3621] CHIP:BLE: Device 36:51:55:64:55:D8 does not look like a CHIP device. [1652388156.272568][3618:3621] CHIP:BLE: Device B4:E3:F9:0A:50:63 does not look like a CHIP device. [1652388156.275733][3618:3621] CHIP:BLE: Device 52:01:4A:BF:7E:BD does not look like a CHIP device. [1652388156.307125][3618:3621] CHIP:BLE: New device scanned: BC:33:AC:FA:55:C1 [1652388156.307251][3618:3621] CHIP:BLE: Device discriminator match. Attempting to connect. [1652388156.311419][3618:3621] CHIP:BLE: Scan complete notification without an active scan. [1652388156.472750][3618:3621] CHIP:DL: ConnectDevice complete [1652388156.909325][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909373][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909408][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0001 [1652388156.909429][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909453][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0001 [1652388156.909473][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909497][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0001 [1652388156.909516][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909546][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0001 [1652388156.909566][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909588][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0001 [1652388156.909608][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909630][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0001 [1652388156.909650][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909675][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service000e [1652388156.909695][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909717][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service000e [1652388156.909736][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909758][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service000e [1652388156.909778][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909803][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service000e [1652388156.909823][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909845][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service000e [1652388156.909865][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909887][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service000e [1652388156.909907][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909933][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0001 [1652388156.909953][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.909975][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0001 [1652388156.909994][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.910016][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0001 [1652388156.910036][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.910060][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service001b [1652388156.910079][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.910138][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service001b [1652388156.910161][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.910185][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service001b [1652388156.910205][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.910232][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.910252][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.910276][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.910295][3618:3621] CHIP:DL: Char1 /org/bluez/hci0/dev_BC_33_AC_FA_55_C1/service0015 [1652388156.910325][3618:3621] CHIP:DL: New BLE connection 0xffff9c048190, device BC:33:AC:FA:55:C1, path /org/bluez/hci0/dev_BC_33_AC_FA_55_C1 [1652388156.910469][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16385 [1652388156.910509][3618:3623] CHIP:IN: BleConnectionComplete: endPoint 0xaaaae4f58860 [1652388157.347665][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388157.445461][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1652388157.445537][3618:3623] CHIP:BLE: subscribe complete, ep = 0xaaaae4f58860 [1652388157.446081][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388157.446334][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388157.446391][3618:3623] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1652388157.446435][3618:3623] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1652388157.446475][3618:3623] CHIP:BLE: local and remote recv window size = 5 [1652388157.446645][3618:3623] CHIP:IN: BLE EndPoint 0xaaaae4f58860 Connection Complete [1652388157.542590][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388157.545157][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388157.545430][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388157.545634][3618:3623] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:3236845297 on exchange 48454i [1652388157.545709][3618:3623] CHIP:EM: Found matching exchange: 48454i, Delegate: 0xffff90000bb0 [1652388157.545795][3618:3623] CHIP:SC: Received PBKDF param response [1652388157.545883][3618:3623] CHIP:SC: Peer assigned session ID 13803 [1652388157.545954][3618:3623] CHIP:SC: Found MRP parameters in the message [1652388157.557706][3618:3623] CHIP:IN: Prepared unauthenticated message 0xffff97ffd898 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 48454i with MessageCounter:2791243023. [1652388157.557763][3618:3623] CHIP:IN: Sending unauthenticated msg 0xffff97ffd898 with MessageCounter:2791243023 to 0x0000000000000000 at monotonic time: 00000000013AD703 msec [1652388157.557874][3618:3623] CHIP:SC: Sent spake2p msg1 [1652388157.639733][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388158.032264][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.032809][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.033018][3618:3623] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:3236845298 on exchange 48454i [1652388158.033089][3618:3623] CHIP:EM: Found matching exchange: 48454i, Delegate: 0xffff90000bb0 [1652388158.033166][3618:3623] CHIP:SC: Received spake2p msg2 [1652388158.036446][3618:3623] CHIP:IN: Prepared unauthenticated message 0xffff97ffd9d8 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 48454i with MessageCounter:2791243024. [1652388158.036549][3618:3623] CHIP:IN: Sending unauthenticated msg 0xffff97ffd9d8 with MessageCounter:2791243024 to 0x0000000000000000 at monotonic time: 00000000013AD8E2 msec [1652388158.036744][3618:3623] CHIP:SC: Sent spake2p msg3 [1652388158.127616][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388158.129112][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.129387][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.129588][3618:3623] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:3236845299 on exchange 48454i [1652388158.129688][3618:3623] CHIP:EM: Found matching exchange: 48454i, Delegate: 0xffff90000bb0 [1652388158.129968][3618:3623] CHIP:IN: New secure session created for device , LSID:36224 PSID:13803! [1652388158.130066][3618:3623] CHIP:CTL: Remote device completed SPAKE2+ handshake [1652388158.130186][3618:3623] CHIP:TOO: Pairing Success [1652388158.130312][3618:3623] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1652388158.130364][3618:3623] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1652388158.130413][3618:3623] CHIP:CTL: Sending request for commissioning information [1652388158.130505][3618:3623] CHIP:DMG: SendReadRequest ReadClient[0xffff90009000]: Sending Read Request [1652388158.130781][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffd208 to 0xFFFFFFFB00000000 (0) of type 0x2 and protocolId (0, 1) on exchange 48455i with MessageCounter:10785083. [1652388158.130869][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffd208 with MessageCounter:10785083 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AD940 msec [1652388158.131148][3618:3623] CHIP:DMG: MoveToState ReadClient[0xffff90009000]: Moving to [AwaitingIn] [1652388158.225019][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388158.228525][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.228863][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.228993][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.229121][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.229306][3618:3623] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:8969627 on exchange 48455i [1652388158.229376][3618:3623] CHIP:EM: Found matching exchange: 48455i, Delegate: 0xffff90009000 [1652388158.229570][3618:3623] CHIP:DMG: ReportDataMessage = [1652388158.229630][3618:3623] CHIP:DMG: { [1652388158.229680][3618:3623] CHIP:DMG: AttributeReportIBs = [1652388158.229750][3618:3623] CHIP:DMG: [ [1652388158.229806][3618:3623] CHIP:DMG: AttributeReportIB = [1652388158.229887][3618:3623] CHIP:DMG: { [1652388158.229951][3618:3623] CHIP:DMG: AttributeDataIB = [1652388158.230027][3618:3623] CHIP:DMG: { [1652388158.230150][3618:3623] CHIP:DMG: DataVersion = 0xe14234ea, [1652388158.230229][3618:3623] CHIP:DMG: AttributePathIB = [1652388158.230307][3618:3623] CHIP:DMG: { [1652388158.230386][3618:3623] CHIP:DMG: Endpoint = 0x0, [1652388158.230468][3618:3623] CHIP:DMG: Cluster = 0x31, [1652388158.230556][3618:3623] CHIP:DMG: Attribute = 0x0000_0003, [1652388158.230640][3618:3623] CHIP:DMG: } [1652388158.230720][3618:3623] CHIP:DMG: [1652388158.230800][3618:3623] CHIP:DMG: Data = 20, [1652388158.230874][3618:3623] CHIP:DMG: }, [1652388158.230953][3618:3623] CHIP:DMG: [1652388158.231016][3618:3623] CHIP:DMG: }, [1652388158.231103][3618:3623] CHIP:DMG: [1652388158.231158][3618:3623] CHIP:DMG: AttributeReportIB = [1652388158.231234][3618:3623] CHIP:DMG: { [1652388158.231298][3618:3623] CHIP:DMG: AttributeDataIB = [1652388158.231370][3618:3623] CHIP:DMG: { [1652388158.231450][3618:3623] CHIP:DMG: DataVersion = 0xe7f1c973, [1652388158.231522][3618:3623] CHIP:DMG: AttributePathIB = [1652388158.231597][3618:3623] CHIP:DMG: { [1652388158.231681][3618:3623] CHIP:DMG: Endpoint = 0x0, [1652388158.231762][3618:3623] CHIP:DMG: Cluster = 0x28, [1652388158.231849][3618:3623] CHIP:DMG: Attribute = 0x0000_0004, [1652388158.231924][3618:3623] CHIP:DMG: } [1652388158.232010][3618:3623] CHIP:DMG: [1652388158.232086][3618:3623] CHIP:DMG: Data = 32773, [1652388158.232167][3618:3623] CHIP:DMG: }, [1652388158.232245][3618:3623] CHIP:DMG: [1652388158.232307][3618:3623] CHIP:DMG: }, [1652388158.232395][3618:3623] CHIP:DMG: [1652388158.232450][3618:3623] CHIP:DMG: AttributeReportIB = [1652388158.232525][3618:3623] CHIP:DMG: { [1652388158.232588][3618:3623] CHIP:DMG: AttributeDataIB = [1652388158.232658][3618:3623] CHIP:DMG: { [1652388158.232736][3618:3623] CHIP:DMG: DataVersion = 0xe7f1c973, [1652388158.232807][3618:3623] CHIP:DMG: AttributePathIB = [1652388158.232881][3618:3623] CHIP:DMG: { [1652388158.232963][3618:3623] CHIP:DMG: Endpoint = 0x0, [1652388158.233211][3618:3623] CHIP:DMG: Cluster = 0x28, [1652388158.233294][3618:3623] CHIP:DMG: Attribute = 0x0000_0002, [1652388158.233370][3618:3623] CHIP:DMG: } [1652388158.233455][3618:3623] CHIP:DMG: [1652388158.233532][3618:3623] CHIP:DMG: Data = 65521, [1652388158.233605][3618:3623] CHIP:DMG: }, [1652388158.233688][3618:3623] CHIP:DMG: [1652388158.233749][3618:3623] CHIP:DMG: }, [1652388158.233834][3618:3623] CHIP:DMG: [1652388158.233889][3618:3623] CHIP:DMG: AttributeReportIB = [1652388158.233964][3618:3623] CHIP:DMG: { [1652388158.234027][3618:3623] CHIP:DMG: AttributeDataIB = [1652388158.234129][3618:3623] CHIP:DMG: { [1652388158.234205][3618:3623] CHIP:DMG: DataVersion = 0x97b319b4, [1652388158.234277][3618:3623] CHIP:DMG: AttributePathIB = [1652388158.234351][3618:3623] CHIP:DMG: { [1652388158.234427][3618:3623] CHIP:DMG: Endpoint = 0x0, [1652388158.234505][3618:3623] CHIP:DMG: Cluster = 0x30, [1652388158.234567][3618:3623] CHIP:DMG: Attribute = 0x0000_0003, [1652388158.234607][3618:3623] CHIP:DMG: } [1652388158.234650][3618:3623] CHIP:DMG: [1652388158.234756][3618:3623] CHIP:DMG: Data = 0, [1652388158.234800][3618:3623] CHIP:DMG: }, [1652388158.234845][3618:3623] CHIP:DMG: [1652388158.234879][3618:3623] CHIP:DMG: }, [1652388158.234925][3618:3623] CHIP:DMG: [1652388158.234954][3618:3623] CHIP:DMG: AttributeReportIB = [1652388158.234996][3618:3623] CHIP:DMG: { [1652388158.235029][3618:3623] CHIP:DMG: AttributeDataIB = [1652388158.235068][3618:3623] CHIP:DMG: { [1652388158.235111][3618:3623] CHIP:DMG: DataVersion = 0x97b319b4, [1652388158.235149][3618:3623] CHIP:DMG: AttributePathIB = [1652388158.235193][3618:3623] CHIP:DMG: { [1652388158.235237][3618:3623] CHIP:DMG: Endpoint = 0x0, [1652388158.235281][3618:3623] CHIP:DMG: Cluster = 0x30, [1652388158.235324][3618:3623] CHIP:DMG: Attribute = 0x0000_0002, [1652388158.235368][3618:3623] CHIP:DMG: } [1652388158.235414][3618:3623] CHIP:DMG: [1652388158.235454][3618:3623] CHIP:DMG: Data = 0, [1652388158.235498][3618:3623] CHIP:DMG: }, [1652388158.235539][3618:3623] CHIP:DMG: [1652388158.235573][3618:3623] CHIP:DMG: }, [1652388158.235619][3618:3623] CHIP:DMG: [1652388158.235648][3618:3623] CHIP:DMG: AttributeReportIB = [1652388158.235690][3618:3623] CHIP:DMG: { [1652388158.235724][3618:3623] CHIP:DMG: AttributeDataIB = [1652388158.235762][3618:3623] CHIP:DMG: { [1652388158.235804][3618:3623] CHIP:DMG: DataVersion = 0x97b319b4, [1652388158.235843][3618:3623] CHIP:DMG: AttributePathIB = [1652388158.235887][3618:3623] CHIP:DMG: { [1652388158.235927][3618:3623] CHIP:DMG: Endpoint = 0x0, [1652388158.235972][3618:3623] CHIP:DMG: Cluster = 0x30, [1652388158.236015][3618:3623] CHIP:DMG: Attribute = 0x0000_0001, [1652388158.236059][3618:3623] CHIP:DMG: } [1652388158.236101][3618:3623] CHIP:DMG: [1652388158.236144][3618:3623] CHIP:DMG: Data = [1652388158.236186][3618:3623] CHIP:DMG: { [1652388158.236235][3618:3623] CHIP:DMG: 0x0 = 60, [1652388158.236285][3618:3623] CHIP:DMG: }, [1652388158.236326][3618:3623] CHIP:DMG: }, [1652388158.236371][3618:3623] CHIP:DMG: [1652388158.236404][3618:3623] CHIP:DMG: }, [1652388158.236452][3618:3623] CHIP:DMG: [1652388158.236482][3618:3623] CHIP:DMG: AttributeReportIB = [1652388158.236522][3618:3623] CHIP:DMG: { [1652388158.236556][3618:3623] CHIP:DMG: AttributeDataIB = [1652388158.236594][3618:3623] CHIP:DMG: { [1652388158.236636][3618:3623] CHIP:DMG: DataVersion = 0x97b319b4, [1652388158.236675][3618:3623] CHIP:DMG: AttributePathIB = [1652388158.236715][3618:3623] CHIP:DMG: { [1652388158.236760][3618:3623] CHIP:DMG: Endpoint = 0x0, [1652388158.236806][3618:3623] CHIP:DMG: Cluster = 0x30, [1652388158.236853][3618:3623] CHIP:DMG: Attribute = 0x0000_0000, [1652388158.236897][3618:3623] CHIP:DMG: } [1652388158.236943][3618:3623] CHIP:DMG: [1652388158.236984][3618:3623] CHIP:DMG: Data = 0, [1652388158.237024][3618:3623] CHIP:DMG: }, [1652388158.237069][3618:3623] CHIP:DMG: [1652388158.237102][3618:3623] CHIP:DMG: }, [1652388158.237148][3618:3623] CHIP:DMG: [1652388158.237178][3618:3623] CHIP:DMG: AttributeReportIB = [1652388158.237220][3618:3623] CHIP:DMG: { [1652388158.237254][3618:3623] CHIP:DMG: AttributeDataIB = [1652388158.237295][3618:3623] CHIP:DMG: { [1652388158.237334][3618:3623] CHIP:DMG: DataVersion = 0xe14234ea, [1652388158.237373][3618:3623] CHIP:DMG: AttributePathIB = [1652388158.237413][3618:3623] CHIP:DMG: { [1652388158.237454][3618:3623] CHIP:DMG: Endpoint = 0x0, [1652388158.237500][3618:3623] CHIP:DMG: Cluster = 0x31, [1652388158.237544][3618:3623] CHIP:DMG: Attribute = 0x0000_FFFC, [1652388158.237585][3618:3623] CHIP:DMG: } [1652388158.237627][3618:3623] CHIP:DMG: [1652388158.237669][3618:3623] CHIP:DMG: Data = 2, [1652388158.237713][3618:3623] CHIP:DMG: }, [1652388158.237757][3618:3623] CHIP:DMG: [1652388158.237790][3618:3623] CHIP:DMG: }, [1652388158.237830][3618:3623] CHIP:DMG: [1652388158.237859][3618:3623] CHIP:DMG: ], [1652388158.237931][3618:3623] CHIP:DMG: [1652388158.237963][3618:3623] CHIP:DMG: SuppressResponse = true, [1652388158.237994][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388158.238022][3618:3623] CHIP:DMG: } [1652388158.239010][3618:3623] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1652388158.239059][3618:3623] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' [1652388158.239087][3618:3623] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1652388158.239117][3618:3623] CHIP:CTL: Arming failsafe (60 seconds) [1652388158.239202][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388158.239240][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388158.239359][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffd008 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 48456i with MessageCounter:10785084. [1652388158.239413][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffd008 with MessageCounter:10785084 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AD9AD msec [1652388158.239540][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388158.322733][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388158.324276][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.324548][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.324786][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:8969628 on exchange 48456i [1652388158.324855][3618:3623] CHIP:EM: Found matching exchange: 48456i, Delegate: 0xffff9000e970 [1652388158.324930][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388158.325023][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388158.325076][3618:3623] CHIP:DMG: { [1652388158.325128][3618:3623] CHIP:DMG: suppressResponse = false, [1652388158.325184][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388158.325255][3618:3623] CHIP:DMG: [ [1652388158.325309][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388158.325395][3618:3623] CHIP:DMG: { [1652388158.325459][3618:3623] CHIP:DMG: CommandDataIB = [1652388158.325537][3618:3623] CHIP:DMG: { [1652388158.325611][3618:3623] CHIP:DMG: CommandPathIB = [1652388158.325693][3618:3623] CHIP:DMG: { [1652388158.325777][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388158.325864][3618:3623] CHIP:DMG: ClusterId = 0x30, [1652388158.325945][3618:3623] CHIP:DMG: CommandId = 0x1, [1652388158.326027][3618:3623] CHIP:DMG: }, [1652388158.326162][3618:3623] CHIP:DMG: [1652388158.326235][3618:3623] CHIP:DMG: CommandData = [1652388158.326310][3618:3623] CHIP:DMG: { [1652388158.326388][3618:3623] CHIP:DMG: 0x0 = 0, [1652388158.326477][3618:3623] CHIP:DMG: 0x1 = "", [1652388158.326554][3618:3623] CHIP:DMG: }, [1652388158.326626][3618:3623] CHIP:DMG: }, [1652388158.326706][3618:3623] CHIP:DMG: [1652388158.326767][3618:3623] CHIP:DMG: }, [1652388158.326841][3618:3623] CHIP:DMG: [1652388158.326894][3618:3623] CHIP:DMG: ], [1652388158.326962][3618:3623] CHIP:DMG: [1652388158.327014][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388158.327070][3618:3623] CHIP:DMG: }, [1652388158.327208][3618:3623] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1652388158.327310][3618:3623] CHIP:CTL: Received ArmFailSafe response [1652388158.327369][3618:3623] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1652388158.327417][3618:3623] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1652388158.327468][3618:3623] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1652388158.327513][3618:3623] CHIP:CTL: Setting Regulatory Config [1652388158.327557][3618:3623] CHIP:CTL: Device does not support configurable regulatory location [1652388158.327668][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388158.327739][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388158.327897][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffcb18 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 48457i with MessageCounter:10785085. [1652388158.328005][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffcb18 with MessageCounter:10785085 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013ADA05 msec [1652388158.328193][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388158.328309][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388158.420190][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388158.421764][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.422037][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.422339][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:8969629 on exchange 48457i [1652388158.422410][3618:3623] CHIP:EM: Found matching exchange: 48457i, Delegate: 0xffff9000eac0 [1652388158.422484][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388158.422577][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388158.422637][3618:3623] CHIP:DMG: { [1652388158.422689][3618:3623] CHIP:DMG: suppressResponse = false, [1652388158.422744][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388158.422815][3618:3623] CHIP:DMG: [ [1652388158.422869][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388158.422945][3618:3623] CHIP:DMG: { [1652388158.423007][3618:3623] CHIP:DMG: CommandDataIB = [1652388158.423073][3618:3623] CHIP:DMG: { [1652388158.423132][3618:3623] CHIP:DMG: CommandPathIB = [1652388158.423214][3618:3623] CHIP:DMG: { [1652388158.423298][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388158.423383][3618:3623] CHIP:DMG: ClusterId = 0x30, [1652388158.423463][3618:3623] CHIP:DMG: CommandId = 0x3, [1652388158.423536][3618:3623] CHIP:DMG: }, [1652388158.423616][3618:3623] CHIP:DMG: [1652388158.423684][3618:3623] CHIP:DMG: CommandData = [1652388158.423758][3618:3623] CHIP:DMG: { [1652388158.423843][3618:3623] CHIP:DMG: 0x0 = 0, [1652388158.423931][3618:3623] CHIP:DMG: 0x1 = "", [1652388158.424010][3618:3623] CHIP:DMG: }, [1652388158.424073][3618:3623] CHIP:DMG: }, [1652388158.424149][3618:3623] CHIP:DMG: [1652388158.424210][3618:3623] CHIP:DMG: }, [1652388158.424281][3618:3623] CHIP:DMG: [1652388158.424333][3618:3623] CHIP:DMG: ], [1652388158.424401][3618:3623] CHIP:DMG: [1652388158.424620][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388158.424677][3618:3623] CHIP:DMG: }, [1652388158.424817][3618:3623] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1652388158.424891][3618:3623] CHIP:CTL: Received SetRegulatoryConfig response [1652388158.424946][3618:3623] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1652388158.424993][3618:3623] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1652388158.425044][3618:3623] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1652388158.425084][3618:3623] CHIP:CTL: Sending request for PAI certificate [1652388158.425118][3618:3623] CHIP:CTL: Sending Certificate Chain request to 0xffff90000b60 device [1652388158.425223][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388158.425314][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388158.425471][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffca68 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 48458i with MessageCounter:10785086. [1652388158.425559][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffca68 with MessageCounter:10785086 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013ADA67 msec [1652388158.425743][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388158.425861][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388158.517638][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388158.521020][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.521305][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.523761][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.524082][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.524214][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.524453][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.524688][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:8969630 on exchange 48458i [1652388158.524754][3618:3623] CHIP:EM: Found matching exchange: 48458i, Delegate: 0xffff9000e970 [1652388158.524835][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388158.524927][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388158.524980][3618:3623] CHIP:DMG: { [1652388158.525032][3618:3623] CHIP:DMG: suppressResponse = false, [1652388158.525087][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388158.525156][3618:3623] CHIP:DMG: [ [1652388158.525210][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388158.525288][3618:3623] CHIP:DMG: { [1652388158.525351][3618:3623] CHIP:DMG: CommandDataIB = [1652388158.525428][3618:3623] CHIP:DMG: { [1652388158.525496][3618:3623] CHIP:DMG: CommandPathIB = [1652388158.525573][3618:3623] CHIP:DMG: { [1652388158.525651][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388158.525738][3618:3623] CHIP:DMG: ClusterId = 0x3e, [1652388158.525817][3618:3623] CHIP:DMG: CommandId = 0x3, [1652388158.525898][3618:3623] CHIP:DMG: }, [1652388158.525983][3618:3623] CHIP:DMG: [1652388158.526051][3618:3623] CHIP:DMG: CommandData = [1652388158.526206][3618:3623] CHIP:DMG: { [1652388158.526315][3618:3623] CHIP:DMG: 0x0 = [ [1652388158.526389][3618:3623] CHIP:DMG: ... (byte string too long) ... [1652388158.526484][3618:3623] CHIP:DMG: ] [1652388158.526561][3618:3623] CHIP:DMG: }, [1652388158.526640][3618:3623] CHIP:DMG: }, [1652388158.526726][3618:3623] CHIP:DMG: [1652388158.526787][3618:3623] CHIP:DMG: }, [1652388158.526861][3618:3623] CHIP:DMG: [1652388158.526913][3618:3623] CHIP:DMG: ], [1652388158.526982][3618:3623] CHIP:DMG: [1652388158.527036][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388158.527087][3618:3623] CHIP:DMG: }, [1652388158.527228][3618:3623] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1652388158.527299][3618:3623] CHIP:CTL: Received certificate chain from the device [1652388158.527355][3618:3623] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest' [1652388158.527411][3618:3623] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' [1652388158.527463][3618:3623] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' [1652388158.527509][3618:3623] CHIP:CTL: Sending request for DAC certificate [1652388158.527552][3618:3623] CHIP:CTL: Sending Certificate Chain request to 0xffff90000b60 device [1652388158.527658][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388158.527722][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388158.527831][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffca18 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 48459i with MessageCounter:10785087. [1652388158.527896][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffca18 with MessageCounter:10785087 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013ADACD msec [1652388158.528017][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388158.528086][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388158.615078][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388158.618577][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.618872][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.621249][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.621544][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.621820][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.622012][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.622229][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:8969631 on exchange 48459i [1652388158.622279][3618:3623] CHIP:EM: Found matching exchange: 48459i, Delegate: 0xffff9000eac0 [1652388158.622341][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388158.622411][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388158.622448][3618:3623] CHIP:DMG: { [1652388158.622483][3618:3623] CHIP:DMG: suppressResponse = false, [1652388158.622521][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388158.622569][3618:3623] CHIP:DMG: [ [1652388158.622606][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388158.622664][3618:3623] CHIP:DMG: { [1652388158.622706][3618:3623] CHIP:DMG: CommandDataIB = [1652388158.622750][3618:3623] CHIP:DMG: { [1652388158.622794][3618:3623] CHIP:DMG: CommandPathIB = [1652388158.622846][3618:3623] CHIP:DMG: { [1652388158.622899][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388158.622955][3618:3623] CHIP:DMG: ClusterId = 0x3e, [1652388158.623009][3618:3623] CHIP:DMG: CommandId = 0x3, [1652388158.623060][3618:3623] CHIP:DMG: }, [1652388158.623108][3618:3623] CHIP:DMG: [1652388158.623167][3618:3623] CHIP:DMG: CommandData = [1652388158.623217][3618:3623] CHIP:DMG: { [1652388158.623265][3618:3623] CHIP:DMG: 0x0 = [ [1652388158.623315][3618:3623] CHIP:DMG: ... (byte string too long) ... [1652388158.623365][3618:3623] CHIP:DMG: ] [1652388158.623420][3618:3623] CHIP:DMG: }, [1652388158.623468][3618:3623] CHIP:DMG: }, [1652388158.623517][3618:3623] CHIP:DMG: [1652388158.623555][3618:3623] CHIP:DMG: }, [1652388158.623600][3618:3623] CHIP:DMG: [1652388158.623636][3618:3623] CHIP:DMG: ], [1652388158.623685][3618:3623] CHIP:DMG: [1652388158.623720][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388158.623755][3618:3623] CHIP:DMG: }, [1652388158.623851][3618:3623] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1652388158.623901][3618:3623] CHIP:CTL: Received certificate chain from the device [1652388158.623942][3618:3623] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest' [1652388158.623984][3618:3623] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' [1652388158.624020][3618:3623] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' [1652388158.624052][3618:3623] CHIP:CTL: Sending Attestation Request to the device. [1652388158.624083][3618:3623] CHIP:CTL: Sending Attestation request to 0xffff90000b60 device [1652388158.624156][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388158.624203][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388158.624320][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffc9d8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 48460i with MessageCounter:10785088. [1652388158.624381][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffc9d8 with MessageCounter:10785088 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013ADB2E msec [1652388158.624522][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388158.624569][3618:3623] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1652388158.624637][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388158.712154][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388158.813226][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.813503][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.815647][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.815925][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.818060][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388158.818407][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388158.818679][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:8969632 on exchange 48460i [1652388158.818749][3618:3623] CHIP:EM: Found matching exchange: 48460i, Delegate: 0xffff9000e970 [1652388158.818832][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388158.818930][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388158.818985][3618:3623] CHIP:DMG: { [1652388158.819037][3618:3623] CHIP:DMG: suppressResponse = false, [1652388158.819092][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388158.819166][3618:3623] CHIP:DMG: [ [1652388158.819220][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388158.819307][3618:3623] CHIP:DMG: { [1652388158.819368][3618:3623] CHIP:DMG: CommandDataIB = [1652388158.819430][3618:3623] CHIP:DMG: { [1652388158.819494][3618:3623] CHIP:DMG: CommandPathIB = [1652388158.819564][3618:3623] CHIP:DMG: { [1652388158.819640][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388158.819714][3618:3623] CHIP:DMG: ClusterId = 0x3e, [1652388158.819799][3618:3623] CHIP:DMG: CommandId = 0x1, [1652388158.819874][3618:3623] CHIP:DMG: }, [1652388158.819947][3618:3623] CHIP:DMG: [1652388158.820020][3618:3623] CHIP:DMG: CommandData = [1652388158.820095][3618:3623] CHIP:DMG: { [1652388158.820177][3618:3623] CHIP:DMG: 0x0 = [ [1652388158.820260][3618:3623] CHIP:DMG: ... (byte string too long) ... [1652388158.820327][3618:3623] CHIP:DMG: ] [1652388158.820400][3618:3623] CHIP:DMG: 0x1 = [ [1652388158.820504][3618:3623] CHIP:DMG: 0xf2, 0x60, 0x6f, 0x7d, 0x8b, 0x4f, 0x7c, 0x81, 0xff, 0x59, 0xeb, 0x39, 0x67, 0xad, 0xfc, 0x54, 0x8d, 0x4a, 0x51, 0x4f, 0xaf, 0xf6, 0xd9, 0x87, 0x5a, 0x4b, 0x2, 0xf2, 0x1b, 0x57, 0x48, 0x12, 0x1, 0xdf, 0x42, 0x10, 0x4c, 0x4a, 0x17, 0x8e, 0xbd, 0x5a, [1652388158.820600][3618:3623] CHIP:DMG: ] [1652388158.820677][3618:3623] CHIP:DMG: }, [1652388158.820744][3618:3623] CHIP:DMG: }, [1652388158.820820][3618:3623] CHIP:DMG: [1652388158.820878][3618:3623] CHIP:DMG: }, [1652388158.820949][3618:3623] CHIP:DMG: [1652388158.821002][3618:3623] CHIP:DMG: ], [1652388158.821073][3618:3623] CHIP:DMG: [1652388158.821122][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388158.821174][3618:3623] CHIP:DMG: }, [1652388158.821316][3618:3623] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1652388158.821391][3618:3623] CHIP:CTL: Received Attestation Information from the device [1652388158.821449][3618:3623] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest' [1652388158.821583][3618:3623] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' [1652388158.821641][3618:3623] CHIP:CTL: Performing next commissioning step 'AttestationVerification' [1652388158.821681][3618:3623] CHIP:CTL: Verifying attestation [1652388158.828512][3618:3623] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1652388158.828577][3618:3623] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification' [1652388158.828606][3618:3623] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' [1652388158.828635][3618:3623] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' [1652388158.828662][3618:3623] CHIP:CTL: Sending CSR request to 0xffff90000b60 device [1652388158.828746][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388158.828787][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388158.828909][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffc0b8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 48461i with MessageCounter:10785089. [1652388158.828960][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffc0b8 with MessageCounter:10785089 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013ADBFA msec [1652388158.829092][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388158.829133][3618:3623] CHIP:CTL: Sent CSR request, waiting for the CSR [1652388158.829199][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388158.907656][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388159.203261][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388159.203550][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388159.204590][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388159.204856][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388159.205084][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:8969633 on exchange 48461i [1652388159.205154][3618:3623] CHIP:EM: Found matching exchange: 48461i, Delegate: 0xffff9c04b130 [1652388159.205240][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388159.205341][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388159.205395][3618:3623] CHIP:DMG: { [1652388159.205448][3618:3623] CHIP:DMG: suppressResponse = false, [1652388159.205505][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388159.205579][3618:3623] CHIP:DMG: [ [1652388159.205633][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388159.205751][3618:3623] CHIP:DMG: { [1652388159.205823][3618:3623] CHIP:DMG: CommandDataIB = [1652388159.205894][3618:3623] CHIP:DMG: { [1652388159.205970][3618:3623] CHIP:DMG: CommandPathIB = [1652388159.206047][3618:3623] CHIP:DMG: { [1652388159.206228][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388159.206321][3618:3623] CHIP:DMG: ClusterId = 0x3e, [1652388159.206401][3618:3623] CHIP:DMG: CommandId = 0x5, [1652388159.206475][3618:3623] CHIP:DMG: }, [1652388159.206556][3618:3623] CHIP:DMG: [1652388159.206622][3618:3623] CHIP:DMG: CommandData = [1652388159.206697][3618:3623] CHIP:DMG: { [1652388159.206780][3618:3623] CHIP:DMG: 0x0 = [ [1652388159.206906][3618:3623] CHIP:DMG: 0x15, 0x30, 0x1, 0xcc, 0x30, 0x81, 0xc9, 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 [1652388159.206988][3618:3623] CHIP:DMG: ] [1652388159.207064][3618:3623] CHIP:DMG: 0x1 = [ [1652388159.207174][3618:3623] CHIP:DMG: 0xdf, 0xa4, 0xae, 0x9f, 0xf0, 0x71, 0x71, 0x7c, 0xf6, 0x25, 0x54, 0x5f, 0x68, 0x31, 0x59, 0xf5, 0x63, 0x75, 0xcf, 0x1d, 0x8f, 0xb9, 0x72, 0xb6, 0xe0, 0x5a, 0x58, 0x71, 0x95, 0xb7, 0xe2, 0x49, 0x59, 0x2c, 0xcf, 0xd7, 0xc8, 0xc0, 0xcc, 0x72, 0x83, 0xf [1652388159.207254][3618:3623] CHIP:DMG: ] [1652388159.207336][3618:3623] CHIP:DMG: }, [1652388159.207413][3618:3623] CHIP:DMG: }, [1652388159.207496][3618:3623] CHIP:DMG: [1652388159.207553][3618:3623] CHIP:DMG: }, [1652388159.207624][3618:3623] CHIP:DMG: [1652388159.207678][3618:3623] CHIP:DMG: ], [1652388159.207742][3618:3623] CHIP:DMG: [1652388159.207794][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388159.207846][3618:3623] CHIP:DMG: }, [1652388159.207990][3618:3623] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1652388159.208065][3618:3623] CHIP:CTL: Received certificate signing request from the device [1652388159.208125][3618:3623] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest' [1652388159.208177][3618:3623] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' [1652388159.208228][3618:3623] CHIP:CTL: Performing next commissioning step 'ValidateCSR' [1652388159.210775][3618:3623] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR' [1652388159.211020][3618:3623] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' [1652388159.211077][3618:3623] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' [1652388159.211129][3618:3623] CHIP:CTL: Getting certificate chain for the device from the issuer [1652388159.211622][3618:3623] CHIP:CTL: Verifying Certificate Signing Request [1652388159.212912][3618:3623] CHIP:CTL: Generating NOC [1652388159.213247][3618:3623] CHIP:CTL: Providing certificate chain to the commissioner [1652388159.213287][3618:3623] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../examples/chip-tool/third_party/connectedhomeip/src/controller/ExampleOperationalCredentialsIssuer.cpp:261: Success [1652388159.213318][3618:3623] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain' [1652388159.213497][3618:3623] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' [1652388159.213527][3618:3623] CHIP:CTL: Sending root certificate to the device [1652388159.213598][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388159.213631][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388159.213747][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffb958 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 48462i with MessageCounter:10785090. [1652388159.213810][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffb958 with MessageCounter:10785090 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013ADD7B msec [1652388159.213929][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388159.213965][3618:3623] CHIP:CTL: Sent root certificate to the device [1652388159.214314][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388159.297632][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388159.394929][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388159.396778][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388159.397042][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388159.397275][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:8969634 on exchange 48462i [1652388159.397345][3618:3623] CHIP:EM: Found matching exchange: 48462i, Delegate: 0xffff9000e970 [1652388159.397422][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388159.397516][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388159.397571][3618:3623] CHIP:DMG: { [1652388159.397624][3618:3623] CHIP:DMG: suppressResponse = false, [1652388159.397679][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388159.397748][3618:3623] CHIP:DMG: [ [1652388159.397802][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388159.397887][3618:3623] CHIP:DMG: { [1652388159.397948][3618:3623] CHIP:DMG: CommandStatusIB = [1652388159.398020][3618:3623] CHIP:DMG: { [1652388159.398120][3618:3623] CHIP:DMG: CommandPathIB = [1652388159.398202][3618:3623] CHIP:DMG: { [1652388159.398280][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388159.398358][3618:3623] CHIP:DMG: ClusterId = 0x3e, [1652388159.398425][3618:3623] CHIP:DMG: CommandId = 0xb, [1652388159.398508][3618:3623] CHIP:DMG: }, [1652388159.398587][3618:3623] CHIP:DMG: [1652388159.398662][3618:3623] CHIP:DMG: StatusIB = [1652388159.398739][3618:3623] CHIP:DMG: { [1652388159.398816][3618:3623] CHIP:DMG: status = 0x00 (SUCCESS), [1652388159.398899][3618:3623] CHIP:DMG: }, [1652388159.398984][3618:3623] CHIP:DMG: [1652388159.399052][3618:3623] CHIP:DMG: }, [1652388159.399130][3618:3623] CHIP:DMG: [1652388159.399187][3618:3623] CHIP:DMG: }, [1652388159.399248][3618:3623] CHIP:DMG: [1652388159.399299][3618:3623] CHIP:DMG: ], [1652388159.399367][3618:3623] CHIP:DMG: [1652388159.399420][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388159.399472][3618:3623] CHIP:DMG: }, [1652388159.399601][3618:3623] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1652388159.399664][3618:3623] CHIP:CTL: Device confirmed that it has received the root certificate [1652388159.399718][3618:3623] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert' [1652388159.399768][3618:3623] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' [1652388159.399820][3618:3623] CHIP:CTL: Performing next commissioning step 'SendNOC' [1652388159.399939][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388159.400013][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388159.400229][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffca08 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 48463i with MessageCounter:10785091. [1652388159.400316][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffca08 with MessageCounter:10785091 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013ADE36 msec [1652388159.400504][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388159.400576][3618:3623] CHIP:CTL: Sent operational certificate to the device [1652388159.400675][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388159.492282][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388159.590183][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388159.687596][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388160.127567][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388160.127847][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388160.128081][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:8969635 on exchange 48463i [1652388160.128151][3618:3623] CHIP:EM: Found matching exchange: 48463i, Delegate: 0xffff9c04b130 [1652388160.128227][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388160.128322][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388160.128376][3618:3623] CHIP:DMG: { [1652388160.128428][3618:3623] CHIP:DMG: suppressResponse = false, [1652388160.128483][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388160.128555][3618:3623] CHIP:DMG: [ [1652388160.128609][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388160.128693][3618:3623] CHIP:DMG: { [1652388160.128763][3618:3623] CHIP:DMG: CommandDataIB = [1652388160.128841][3618:3623] CHIP:DMG: { [1652388160.128903][3618:3623] CHIP:DMG: CommandPathIB = [1652388160.128979][3618:3623] CHIP:DMG: { [1652388160.129058][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388160.129132][3618:3623] CHIP:DMG: ClusterId = 0x3e, [1652388160.129208][3618:3623] CHIP:DMG: CommandId = 0x8, [1652388160.129275][3618:3623] CHIP:DMG: }, [1652388160.129348][3618:3623] CHIP:DMG: [1652388160.129415][3618:3623] CHIP:DMG: CommandData = [1652388160.129489][3618:3623] CHIP:DMG: { [1652388160.129568][3618:3623] CHIP:DMG: 0x0 = 0, [1652388160.129649][3618:3623] CHIP:DMG: 0x1 = 1, [1652388160.129727][3618:3623] CHIP:DMG: }, [1652388160.129796][3618:3623] CHIP:DMG: }, [1652388160.129870][3618:3623] CHIP:DMG: [1652388160.129931][3618:3623] CHIP:DMG: }, [1652388160.130005][3618:3623] CHIP:DMG: [1652388160.130058][3618:3623] CHIP:DMG: ], [1652388160.130240][3618:3623] CHIP:DMG: [1652388160.130300][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388160.130353][3618:3623] CHIP:DMG: }, [1652388160.130493][3618:3623] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1652388160.130568][3618:3623] CHIP:CTL: Device returned status 0 on receiving the NOC [1652388160.130618][3618:3623] CHIP:CTL: Operational credentials provisioned on device 0xffff90000b60 [1652388160.130687][3618:3623] CHIP:TOO: Secure Pairing Success [1652388160.130740][3618:3623] CHIP:CTL: Successfully finished commissioning step 'SendNOC' [1652388160.130784][3618:3623] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'ThreadNetworkSetup' [1652388160.130830][3618:3623] CHIP:CTL: Performing next commissioning step 'ThreadNetworkSetup' [1652388160.130940][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388160.131011][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388160.131177][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffca38 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 48464i with MessageCounter:10785092. [1652388160.131263][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffca38 with MessageCounter:10785092 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AE111 msec [1652388160.131441][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388160.131561][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388160.223859][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388160.225699][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388160.225977][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388160.226222][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:8969636 on exchange 48464i [1652388160.226274][3618:3623] CHIP:EM: Found matching exchange: 48464i, Delegate: 0xffff9000e970 [1652388160.226329][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388160.226396][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388160.226433][3618:3623] CHIP:DMG: { [1652388160.226469][3618:3623] CHIP:DMG: suppressResponse = false, [1652388160.226506][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388160.226553][3618:3623] CHIP:DMG: [ [1652388160.226589][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388160.226646][3618:3623] CHIP:DMG: { [1652388160.226688][3618:3623] CHIP:DMG: CommandDataIB = [1652388160.226736][3618:3623] CHIP:DMG: { [1652388160.226782][3618:3623] CHIP:DMG: CommandPathIB = [1652388160.226837][3618:3623] CHIP:DMG: { [1652388160.226889][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388160.226943][3618:3623] CHIP:DMG: ClusterId = 0x31, [1652388160.227001][3618:3623] CHIP:DMG: CommandId = 0x5, [1652388160.227055][3618:3623] CHIP:DMG: }, [1652388160.227112][3618:3623] CHIP:DMG: [1652388160.227162][3618:3623] CHIP:DMG: CommandData = [1652388160.227212][3618:3623] CHIP:DMG: { [1652388160.227268][3618:3623] CHIP:DMG: 0x0 = 0, [1652388160.227325][3618:3623] CHIP:DMG: 0x2 = 0, [1652388160.227377][3618:3623] CHIP:DMG: }, [1652388160.227423][3618:3623] CHIP:DMG: }, [1652388160.227476][3618:3623] CHIP:DMG: [1652388160.227517][3618:3623] CHIP:DMG: }, [1652388160.227566][3618:3623] CHIP:DMG: [1652388160.227601][3618:3623] CHIP:DMG: ], [1652388160.227647][3618:3623] CHIP:DMG: [1652388160.227682][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388160.227717][3618:3623] CHIP:DMG: }, [1652388160.227812][3618:3623] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005 [1652388160.227888][3618:3623] CHIP:CTL: Received NetworkConfig response [1652388160.227928][3618:3623] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkSetup' [1652388160.227963][3618:3623] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkSetup' -> 'ThreadNetworkEnable' [1652388160.227998][3618:3623] CHIP:CTL: Performing next commissioning step 'ThreadNetworkEnable' [1652388160.228087][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388160.228139][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388160.228257][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffcb08 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 48465i with MessageCounter:10785093. [1652388160.228317][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffcb08 with MessageCounter:10785093 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000013AE172 msec [1652388160.228457][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388160.228537][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388160.321535][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388160.323098][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388160.323387][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388160.323631][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:8969637 on exchange 48465i [1652388160.323702][3618:3623] CHIP:EM: Found matching exchange: 48465i, Delegate: 0xffff9c04b130 [1652388160.323781][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388160.323878][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388160.323933][3618:3623] CHIP:DMG: { [1652388160.323986][3618:3623] CHIP:DMG: suppressResponse = false, [1652388160.324042][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388160.324113][3618:3623] CHIP:DMG: [ [1652388160.324168][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388160.324249][3618:3623] CHIP:DMG: { [1652388160.324313][3618:3623] CHIP:DMG: CommandDataIB = [1652388160.324380][3618:3623] CHIP:DMG: { [1652388160.324450][3618:3623] CHIP:DMG: CommandPathIB = [1652388160.324519][3618:3623] CHIP:DMG: { [1652388160.324604][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388160.324693][3618:3623] CHIP:DMG: ClusterId = 0x31, [1652388160.324764][3618:3623] CHIP:DMG: CommandId = 0x7, [1652388160.324851][3618:3623] CHIP:DMG: }, [1652388160.324923][3618:3623] CHIP:DMG: [1652388160.324992][3618:3623] CHIP:DMG: CommandData = [1652388160.325074][3618:3623] CHIP:DMG: { [1652388160.325152][3618:3623] CHIP:DMG: 0x0 = 0, [1652388160.325232][3618:3623] CHIP:DMG: 0x2 = NULL [1652388160.325310][3618:3623] CHIP:DMG: }, [1652388160.325382][3618:3623] CHIP:DMG: }, [1652388160.325460][3618:3623] CHIP:DMG: [1652388160.325520][3618:3623] CHIP:DMG: }, [1652388160.325592][3618:3623] CHIP:DMG: [1652388160.325644][3618:3623] CHIP:DMG: ], [1652388160.325713][3618:3623] CHIP:DMG: [1652388160.325766][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388160.325819][3618:3623] CHIP:DMG: }, [1652388160.325954][3618:3623] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007 [1652388160.326029][3618:3623] CHIP:CTL: Received ConnectNetwork response [1652388160.326141][3618:3623] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkEnable' [1652388160.326198][3618:3623] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkEnable' -> 'FindOperational' [1652388160.326251][3618:3623] CHIP:CTL: Performing next commissioning step 'FindOperational' [1652388160.326300][3618:3623] CHIP:CSM: FindOrEstablishSession: PeerId = 54076DAA023833D1:0000000000000002 [1652388160.326344][3618:3623] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1652388160.328829][3618:3623] CHIP:DIS: Operational node lookup already in progress. Will NOT start a new one. [1652388160.328945][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388160.526802][3618:3623] CHIP:DIS: Checking node lookup status after 200 ms [1652388162.905333][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388163.326429][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.326538][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.327463][3618:3623] CHIP:DIS: Lookup clearing interface for non LL address [1652388163.327543][3618:3623] CHIP:DIS: UDP:[fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5%eth0]:5540: new best score: 6 [1652388163.327594][3618:3623] CHIP:DIS: Checking node lookup status after 3001 ms [1652388163.327653][3618:3623] CHIP:CTL: Updating device address to UDP:[fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 while in state 1 [1652388163.327697][3618:3623] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000002]: State change 1 --> 2 [1652388163.327940][3618:3623] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000002 [1652388163.329318][3618:3623] CHIP:SC: Including MRP parameters [1652388163.329616][3618:3623] CHIP:IN: Prepared unauthenticated message 0xaaaafe868418 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 48466i with MessageCounter:2791243025. [1652388163.329714][3618:3623] CHIP:IN: Sending unauthenticated msg 0xaaaafe868418 with MessageCounter:2791243025 to 0x0000000000000000 at monotonic time: 00000000013AED8F msec [1652388163.330058][3618:3623] CHIP:SC: Sent Sigma1 msg [1652388163.330171][3618:3623] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000002]: State change 2 --> 3 [1652388163.330246][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.330509][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.330578][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.330639][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.330694][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.330905][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.330971][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.331031][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.331087][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.331437][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.331507][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.331569][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.331625][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.331837][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.331901][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.331963][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.332018][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.332220][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.332288][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.332351][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.332407][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.332609][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.332671][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.332733][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.332787][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.332979][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.333036][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.333088][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.333139][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.333328][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.333383][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.333439][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.333490][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.333671][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.333724][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.333780][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.333830][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.334191][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.334251][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.334308][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.334360][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.334542][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.334596][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.334650][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.334699][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.334877][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.334930][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.334984][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.335033][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388163.335210][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388163.335265][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388163.335320][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388163.335370][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.327312][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.327406][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.327505][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.327560][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.327762][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.327825][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.327945][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.328036][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.328235][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.328298][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.328359][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.328413][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.328737][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.328801][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.328863][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.328918][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.329106][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.329166][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.329224][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.329276][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.329460][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.329520][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.329579][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.329634][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.329818][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.329875][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.329932][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.329984][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.330228][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.330293][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.330353][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.330407][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.330596][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.330654][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.330710][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.330762][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.330944][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.330998][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.331053][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.331103][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.331415][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.331473][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.331530][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.331580][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.331764][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.331820][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.331875][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.331926][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.332105][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.332157][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.332212][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.332262][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.332441][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388164.332495][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388164.332550][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388164.332600][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388164.480074][3618:3623] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:3236845300 on exchange 48466i [1652388164.480166][3618:3623] CHIP:EM: Found matching exchange: 48466i, Delegate: 0xffff90013860 [1652388164.480254][3618:3623] CHIP:EM: Rxd Ack; Removing MessageCounter:2791243025 from Retrans Table on exchange 48466i [1652388164.480313][3618:3623] CHIP:EM: Removed CHIP MessageCounter:2791243025 from RetransTable on exchange 48466i [1652388164.480396][3618:3623] CHIP:SC: Received Sigma2 msg [1652388164.480471][3618:3623] CHIP:SC: Peer assigned session session ID 13804 [1652388164.488360][3618:3623] CHIP:SC: Found MRP parameters in the message [1652388164.488464][3618:3623] CHIP:SC: Sending Sigma3 [1652388164.489176][3618:3623] CHIP:EM: Piggybacking Ack for MessageCounter:3236845300 on exchange: 48466i [1652388164.489287][3618:3623] CHIP:IN: Prepared unauthenticated message 0xaaaafe868418 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 48466i with MessageCounter:2791243026. [1652388164.489380][3618:3623] CHIP:IN: Sending unauthenticated msg 0xaaaafe868418 with MessageCounter:2791243026 to 0x0000000000000000 at monotonic time: 00000000013AF217 msec [1652388164.489758][3618:3623] CHIP:SC: Sent Sigma3 msg [1652388165.440665][3618:3621] CHIP:DL: Indication received, conn = 0xffff9c048190 [1652388165.440978][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1652388166.329101][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.329192][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.329266][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.329329][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.329535][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.329595][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.329656][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.329711][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.329905][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.329965][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.330024][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.330077][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.330492][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.330559][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.330620][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.330675][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.330892][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.330953][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.331016][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.331070][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.331429][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.331569][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.331632][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.331684][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.331982][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.332041][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.332099][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.332172][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.332438][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.332494][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.332571][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.332622][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.332889][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.332947][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.333025][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.333078][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.333343][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.333399][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.333476][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.333527][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.333916][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.333974][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.334031][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.334221][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.334437][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.334493][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.334570][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.334623][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.334885][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.334941][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.334996][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.335046][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.335270][3618:3623] CHIP:DIS: Discovered node without a pending query [1652388166.335391][3618:3623] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388166.335470][3618:3623] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388166.335522][3618:3623] CHIP:DIS: Discovery does not require any more timeouts [1652388166.581024][3618:3623] CHIP:EM: Retransmitting MessageCounter:2791243026 on exchange 48466i Send Cnt 0 [1652388166.581196][3618:3623] CHIP:IN: Sending unauthenticated msg 0xaaaafe868418 with MessageCounter:2791243026 to 0x0000000000000000 at monotonic time: 00000000013AFA43 msec [1652388166.780762][3618:3623] CHIP:IN: Received a duplicate message with MessageCounter:3236845300 on exchange 48466i [1652388166.780850][3618:3623] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:3236845300 on exchange 48466i [1652388166.780913][3618:3623] CHIP:EM: Found matching exchange: 48466i, Delegate: 0xffff90013860 [1652388166.780972][3618:3623] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:3236845300 on exchange 48466i [1652388166.781030][3618:3623] CHIP:EM: Sending Standalone Ack for MessageCounter:3236845300 on exchange 48466i [1652388166.781107][3618:3623] CHIP:IN: Prepared unauthenticated message 0xffff97ffd978 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 48466i with MessageCounter:2791243027. [1652388166.781190][3618:3623] CHIP:IN: Sending unauthenticated msg 0xffff97ffd978 with MessageCounter:2791243027 to 0x0000000000000000 at monotonic time: 00000000013AFB0B msec [1652388168.023989][3618:3623] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1652388168.069906][3618:3623] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:3236845301 on exchange 48466i [1652388168.069984][3618:3623] CHIP:EM: Found matching exchange: 48466i, Delegate: 0xffff90013860 [1652388168.070059][3618:3623] CHIP:EM: Rxd Ack; Removing MessageCounter:2791243026 from Retrans Table on exchange 48466i [1652388168.070151][3618:3623] CHIP:EM: Removed CHIP MessageCounter:2791243026 from RetransTable on exchange 48466i [1652388168.070225][3618:3623] CHIP:SC: Success status report received. Session was established [1652388168.077565][3618:3623] CHIP:IN: New secure session created for device <0000000000000002, 1>, LSID:36225 PSID:13804! [1652388168.077650][3618:3623] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000002]: State change 3 --> 4 [1652388168.077746][3618:3623] CHIP:CTL: Successfully finished commissioning step 'FindOperational' [1652388168.077797][3618:3623] CHIP:CTL: Commissioning stage next step: 'FindOperational' -> 'SendComplete' [1652388168.077846][3618:3623] CHIP:CTL: Performing next commissioning step 'SendComplete' [1652388168.077952][3618:3623] CHIP:DMG: ICR moving to [AddingComm] [1652388168.078008][3618:3623] CHIP:DMG: ICR moving to [AddedComma] [1652388168.078283][3618:3623] CHIP:IN: Prepared secure message 0xaaaafe868418 to 0x0000000000000002 (1) of type 0x8 and protocolId (0, 1) on exchange 48467i with MessageCounter:12472110. [1652388168.078368][3618:3623] CHIP:IN: Sending encrypted msg 0xaaaafe868418 with MessageCounter:12472110 to 0x0000000000000002 (1) at monotonic time: 00000000013B001C msec [1652388168.078831][3618:3623] CHIP:DMG: ICR moving to [CommandSen] [1652388168.078919][3618:3623] CHIP:EM: Sending Standalone Ack for MessageCounter:3236845301 on exchange 48466i [1652388168.078997][3618:3623] CHIP:IN: Prepared unauthenticated message 0xffff97ffd9d8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 48466i with MessageCounter:2791243028. [1652388168.079139][3618:3623] CHIP:IN: Sending unauthenticated msg 0xffff97ffd9d8 with MessageCounter:2791243028 to 0x0000000000000000 at monotonic time: 00000000013B001D msec [1652388168.079360][3618:3623] CHIP:EM: Flushed pending ack for MessageCounter:3236845301 on exchange 48466i [1652388168.136788][3618:3623] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:14146570 on exchange 48467i [1652388168.136872][3618:3623] CHIP:EM: Found matching exchange: 48467i, Delegate: 0xffff9c04b130 [1652388168.136951][3618:3623] CHIP:EM: Rxd Ack; Removing MessageCounter:12472110 from Retrans Table on exchange 48467i [1652388168.137001][3618:3623] CHIP:EM: Removed CHIP MessageCounter:12472110 from RetransTable on exchange 48467i [1652388168.137077][3618:3623] CHIP:DMG: ICR moving to [ResponseRe] [1652388168.137159][3618:3623] CHIP:DMG: InvokeResponseMessage = [1652388168.137203][3618:3623] CHIP:DMG: { [1652388168.137252][3618:3623] CHIP:DMG: suppressResponse = false, [1652388168.137302][3618:3623] CHIP:DMG: InvokeResponseIBs = [1652388168.137365][3618:3623] CHIP:DMG: [ [1652388168.137414][3618:3623] CHIP:DMG: InvokeResponseIB = [1652388168.137489][3618:3623] CHIP:DMG: { [1652388168.137547][3618:3623] CHIP:DMG: CommandDataIB = [1652388168.137609][3618:3623] CHIP:DMG: { [1652388168.137655][3618:3623] CHIP:DMG: CommandPathIB = [1652388168.137706][3618:3623] CHIP:DMG: { [1652388168.137758][3618:3623] CHIP:DMG: EndpointId = 0x0, [1652388168.137813][3618:3623] CHIP:DMG: ClusterId = 0x30, [1652388168.137867][3618:3623] CHIP:DMG: CommandId = 0x5, [1652388168.137937][3618:3623] CHIP:DMG: }, [1652388168.138022][3618:3623] CHIP:DMG: [1652388168.138124][3618:3623] CHIP:DMG: CommandData = [1652388168.138208][3618:3623] CHIP:DMG: { [1652388168.138272][3618:3623] CHIP:DMG: 0x0 = 0, [1652388168.138342][3618:3623] CHIP:DMG: 0x1 = "", [1652388168.138415][3618:3623] CHIP:DMG: }, [1652388168.138484][3618:3623] CHIP:DMG: }, [1652388168.138553][3618:3623] CHIP:DMG: [1652388168.138609][3618:3623] CHIP:DMG: }, [1652388168.138677][3618:3623] CHIP:DMG: [1652388168.138725][3618:3623] CHIP:DMG: ], [1652388168.138779][3618:3623] CHIP:DMG: [1652388168.138825][3618:3623] CHIP:DMG: InteractionModelRevision = 1 [1652388168.138871][3618:3623] CHIP:DMG: }, [1652388168.138994][3618:3623] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1652388168.139062][3618:3623] CHIP:CTL: Received CommissioningComplete response [1652388168.139114][3618:3623] CHIP:CTL: Successfully finished commissioning step 'SendComplete' [1652388168.139158][3618:3623] CHIP:CTL: Commissioning stage next step: 'SendComplete' -> 'Cleanup' [1652388168.139204][3618:3623] CHIP:CTL: Performing next commissioning step 'Cleanup' [1652388168.139250][3618:3623] CHIP:DIS: Closing all BLE connections [1652388168.139296][3618:3623] CHIP:IN: Clearing BLE pending packets. [1652388168.139415][3618:3623] CHIP:BLE: Auto-closing end point's BLE connection. [1652388168.139466][3618:3623] CHIP:DL: Closing BLE GATT connection (con 0xffff9c048190) [1652388168.139590][3618:3623] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1652388168.139645][3618:3623] CHIP:TOO: Device commissioning completed with success [1652388168.139769][3618:3623] CHIP:DMG: ICR moving to [AwaitingDe] [1652388168.139834][3618:3623] CHIP:EM: Sending Standalone Ack for MessageCounter:14146570 on exchange 48467i [1652388168.139893][3618:3621] CHIP:DL: BluezDisconnect peer=BC:33:AC:FA:55:C1 [1652388168.140040][3618:3623] CHIP:IN: Prepared secure message 0xffff97ffd9e8 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 48467i with MessageCounter:12472111. [1652388168.140117][3618:3623] CHIP:IN: Sending encrypted msg 0xffff97ffd9e8 with MessageCounter:12472111 to 0x0000000000000002 (1) at monotonic time: 00000000013B005A msec [1652388168.140340][3618:3623] CHIP:EM: Flushed pending ack for MessageCounter:14146570 on exchange 48467i [1652388168.140785][3618:3618] CHIP:CTL: Shutting down the commissioner [1652388168.140994][3618:3618] CHIP:CTL: Shutting down the controller [1652388168.141047][3618:3618] CHIP:CTL: Shutting down the commissioner [1652388168.141171][3618:3618] CHIP:CTL: Shutting down the controller [1652388168.141222][3618:3618] CHIP:IN: Expiring all connections for fabric 1!! [1652388168.141298][3618:3618] CHIP:CTL: Shutting down the commissioner [1652388168.141430][3618:3618] CHIP:CTL: Shutting down the controller [1652388168.141481][3618:3618] CHIP:IN: Expiring all connections for fabric 2!! [1652388168.141541][3618:3618] CHIP:CTL: Shutting down the commissioner [1652388168.141684][3618:3618] CHIP:CTL: Shutting down the controller [1652388168.141723][3618:3618] CHIP:IN: Expiring all connections for fabric 3!! [1652388168.141776][3618:3618] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1652388168.142626][3618:3618] CHIP:DMG: IM WH moving to [Uninitialized] [1652388168.142702][3618:3618] CHIP:DMG: IM WH moving to [Uninitialized] [1652388168.142739][3618:3618] CHIP:DMG: IM WH moving to [Uninitialized] [1652388168.142779][3618:3618] CHIP:DMG: IM WH moving to [Uninitialized] [1652388168.142822][3618:3618] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388168.142977][3618:3618] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1652388168.143364][3618:3618] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ROdHbM) [1652388168.144374][3618:3618] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388168.144477][3618:3618] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1652388168.144526][3618:3618] CHIP:DL: Inet Layer shutdown [1652388168.144568][3618:3618] CHIP:DL: BLE shutdown [1652388168.146943][3618:3618] CHIP:DL: System Layer shutdown pi@ubuntu:~$ ./chip-tool otasoftwareupdaterequestor announce-ota-provider 1 0 0 0 2 0 [1652388176.283424][3628:3628] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1652388176.283874][3628:3628] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1652388176.284028][3628:3628] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1652388176.284134][3628:3628] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1652388176.284455][3628:3628] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-w7cV2w) [1652388176.285032][3628:3628] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388176.285085][3628:3628] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4) [1652388176.285619][3628:3628] CHIP:DL: Got Ethernet interface: eth0 [1652388176.285949][3628:3628] CHIP:DL: Found the primary Ethernet interface:eth0 [1652388176.286343][3628:3628] CHIP:DL: Got WiFi interface: wlan0 [1652388176.291916][3628:3628] CHIP:DL: Found the primary WiFi interface:wlan0 [1652388176.292016][3628:3628] CHIP:IN: UDP::Init bind&listen port=0 [1652388176.292133][3628:3628] CHIP:IN: UDP::Init bound to port=47480 [1652388176.292158][3628:3628] CHIP:IN: UDP::Init bind&listen port=0 [1652388176.292243][3628:3628] CHIP:IN: UDP::Init bound to port=38356 [1652388176.292266][3628:3628] CHIP:IN: BLEBase::Init - setting/overriding transport [1652388176.292285][3628:3628] CHIP:IN: TransportMgr initialized [1652388176.292320][3628:3628] CHIP:DIS: Init fabric pairing table with server storage [1652388176.292456][3628:3628] CHIP:IN: Loading from storage for fabric index 0x1 [1652388176.294902][3628:3628] CHIP:IN: Loading from storage for fabric index 0x2 [1652388176.295642][3628:3628] CHIP:IN: Loading from storage for fabric index 0x3 [1652388176.296226][3628:3628] CHIP:DIS: Add fabric pairing table delegate [1652388176.299564][3628:3628] CHIP:ZCL: Using ZAP configuration... [1652388176.302762][3628:3628] CHIP:DL: MDNS failed to join multicast group on wpan0 for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1652388176.303954][3628:3628] CHIP:CTL: System State Initialized... [1652388176.304038][3628:3628] CHIP:CTL: Setting attestation nonce to random value [1652388176.304116][3628:3628] CHIP:CTL: Setting CSR nonce to random value [1652388176.304208][3628:3628] CHIP:IN: UDP::Init bind&listen port=5550 [1652388176.304315][3628:3628] CHIP:IN: UDP::Init bound to port=5550 [1652388176.304347][3628:3628] CHIP:IN: UDP::Init bind&listen port=5550 [1652388176.304441][3628:3628] CHIP:IN: UDP::Init bound to port=5550 [1652388176.304471][3628:3628] CHIP:IN: TransportMgr initialized [1652388176.304552][3628:3628] CHIP:CTL: Setting attestation nonce to random value [1652388176.304617][3628:3628] CHIP:CTL: Setting CSR nonce to random value [1652388176.305735][3628:3628] CHIP:CTL: Generating NOC [1652388176.307059][3628:3628] CHIP:DIS: Verifying the received credentials [1652388176.308922][3628:3628] CHIP:DIS: Added new fabric at index: 0x1, Initialized: 1 [1652388176.308962][3628:3628] CHIP:DIS: Assigned compressed fabric ID: 0x54076DAA023833D1, node ID: 0x000000000001B669 [1652388176.308983][3628:3628] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x54076DAA023833D1 [1652388176.309023][3628:3628] CHIP:IN: UDP::Init bind&listen port=5550 [1652388176.309135][3628:3628] CHIP:IN: UDP::Init bound to port=5550 [1652388176.309159][3628:3628] CHIP:IN: UDP::Init bind&listen port=5550 [1652388176.309234][3628:3628] CHIP:IN: UDP::Init bound to port=5550 [1652388176.309256][3628:3628] CHIP:IN: TransportMgr initialized [1652388176.309349][3628:3628] CHIP:CTL: Setting attestation nonce to random value [1652388176.309408][3628:3628] CHIP:CTL: Setting CSR nonce to random value [1652388176.310228][3628:3628] CHIP:CTL: Generating NOC [1652388176.311112][3628:3628] CHIP:DIS: Verifying the received credentials [1652388176.312832][3628:3628] CHIP:DIS: Added new fabric at index: 0x2, Initialized: 1 [1652388176.312869][3628:3628] CHIP:DIS: Assigned compressed fabric ID: 0xBA72F338CA9489BB, node ID: 0x000000000001B669 [1652388176.312891][3628:3628] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xBA72F338CA9489BB [1652388176.312931][3628:3628] CHIP:IN: UDP::Init bind&listen port=5550 [1652388176.313041][3628:3628] CHIP:IN: UDP::Init bound to port=5550 [1652388176.313067][3628:3628] CHIP:IN: UDP::Init bind&listen port=5550 [1652388176.313147][3628:3628] CHIP:IN: UDP::Init bound to port=5550 [1652388176.313169][3628:3628] CHIP:IN: TransportMgr initialized [1652388176.313255][3628:3628] CHIP:CTL: Setting attestation nonce to random value [1652388176.313312][3628:3628] CHIP:CTL: Setting CSR nonce to random value [1652388176.314277][3628:3628] CHIP:CTL: Generating NOC [1652388176.315348][3628:3628] CHIP:DIS: Verifying the received credentials [1652388176.317229][3628:3628] CHIP:DIS: Added new fabric at index: 0x3, Initialized: 1 [1652388176.317276][3628:3628] CHIP:DIS: Assigned compressed fabric ID: 0x682D29C2E3920DF2, node ID: 0x000000000001B669 [1652388176.317297][3628:3628] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x682D29C2E3920DF2 [1652388176.317341][3628:3628] CHIP:IN: UDP::Init bind&listen port=5550 [1652388176.317461][3628:3628] CHIP:IN: UDP::Init bound to port=5550 [1652388176.317486][3628:3628] CHIP:IN: UDP::Init bind&listen port=5550 [1652388176.317567][3628:3628] CHIP:IN: UDP::Init bound to port=5550 [1652388176.317590][3628:3628] CHIP:IN: TransportMgr initialized [1652388176.357382][3628:3633] CHIP:DL: CHIP task running [1652388176.357514][3628:3633] CHIP:TOO: Sending command to node 0x2 [1652388176.357551][3628:3633] CHIP:CSM: FindOrEstablishSession: PeerId = 54076DAA023833D1:0000000000000002 [1652388176.357576][3628:3633] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1652388176.358974][3628:3633] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388176.359031][3628:3633] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388176.359640][3628:3633] CHIP:DIS: Lookup clearing interface for non LL address [1652388176.359691][3628:3633] CHIP:DIS: UDP:[fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5%eth0]:5540: new best score: 6 [1652388176.359719][3628:3633] CHIP:DIS: Checking node lookup status after 2 ms [1652388176.359744][3628:3633] CHIP:DIS: Keeping DNSSD lookup active [1652388176.359925][3628:3633] CHIP:DIS: Discovered node without a pending query [1652388176.359956][3628:3633] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388176.359988][3628:3633] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388176.360404][3628:3633] CHIP:DIS: UDP:[fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5%eth0]:5540: score has not improved: 6 [1652388176.360439][3628:3633] CHIP:DIS: Checking node lookup status after 3 ms [1652388176.360462][3628:3633] CHIP:DIS: Keeping DNSSD lookup active [1652388176.360945][3628:3633] CHIP:DIS: Discovered node without a pending query [1652388176.360978][3628:3633] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388176.361008][3628:3633] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388176.361415][3628:3633] CHIP:DIS: UDP:[fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5%wlan0]:5540: score has not improved: 6 [1652388176.361451][3628:3633] CHIP:DIS: Checking node lookup status after 4 ms [1652388176.361474][3628:3633] CHIP:DIS: Keeping DNSSD lookup active [1652388176.361621][3628:3633] CHIP:DIS: Discovered node without a pending query [1652388176.361652][3628:3633] CHIP:DIS: Node ID resolved for 54076DAA023833D1:0000000000000002 [1652388176.361682][3628:3633] CHIP:DIS: Addr 0: [fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 [1652388176.362074][3628:3633] CHIP:DIS: UDP:[fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5%wlan0]:5540: score has not improved: 6 [1652388176.362142][3628:3633] CHIP:DIS: Checking node lookup status after 5 ms [1652388176.362167][3628:3633] CHIP:DIS: Keeping DNSSD lookup active [1652388176.558278][3628:3633] CHIP:DIS: Checking node lookup status after 201 ms [1652388176.558384][3628:3633] CHIP:CTL: Updating device address to UDP:[fd1d:e078:27ad:f4da:3db5:ec8f:d9f4:e9b5]:5540 while in state 1 [1652388176.558438][3628:3633] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000002]: State change 1 --> 2 [1652388176.558816][3628:3633] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000002 [1652388176.560186][3628:3633] CHIP:SC: Including MRP parameters [1652388176.560623][3628:3633] CHIP:IN: Prepared unauthenticated message 0xaaaad07755d8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 37965i with MessageCounter:2507241899. [1652388176.560721][3628:3633] CHIP:IN: Sending unauthenticated msg 0xaaaad07755d8 with MessageCounter:2507241899 to 0x0000000000000000 at monotonic time: 00000000013B213E msec [1652388176.561049][3628:3633] CHIP:SC: Sent Sigma1 msg [1652388176.561118][3628:3633] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000002]: State change 2 --> 3 [1652388176.561179][3628:3633] CHIP:DIS: Discovery does not require any more timeouts [1652388177.391584][3628:3633] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:3236845302 on exchange 37965i [1652388177.391682][3628:3633] CHIP:EM: Found matching exchange: 37965i, Delegate: 0xffff980015a0 [1652388177.391761][3628:3633] CHIP:EM: Rxd Ack; Removing MessageCounter:2507241899 from Retrans Table on exchange 37965i [1652388177.391821][3628:3633] CHIP:EM: Removed CHIP MessageCounter:2507241899 from RetransTable on exchange 37965i [1652388177.391894][3628:3633] CHIP:SC: Received Sigma2Resume msg [1652388177.392071][3628:3633] CHIP:SC: Found MRP parameters in the message [1652388177.392130][3628:3633] CHIP:SC: Peer assigned session session ID 13805 [1652388177.400313][3628:3633] CHIP:SC: Sending status report. Protocol code 0, exchange 37965 [1652388177.400584][3628:3633] CHIP:EM: Piggybacking Ack for MessageCounter:3236845302 on exchange: 37965i [1652388177.400679][3628:3633] CHIP:IN: Prepared unauthenticated message 0xaaaad07755d8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 37965i with MessageCounter:2507241900. [1652388177.400770][3628:3633] CHIP:IN: Sending unauthenticated msg 0xaaaad07755d8 with MessageCounter:2507241900 to 0x0000000000000000 at monotonic time: 00000000013B2486 msec [1652388177.401261][3628:3633] CHIP:IN: New secure session created for device <0000000000000002, 1>, LSID:15598 PSID:13805! [1652388177.401525][3628:3633] CHIP:CTL: OperationalDeviceProxy[54076DAA023833D1:0000000000000002]: State change 3 --> 4 [1652388177.401627][3628:3633] CHIP:TOO: Sending cluster (0x0000002A) command (0x00000000) on endpoint 0 [1652388177.401758][3628:3633] CHIP:DMG: ICR moving to [AddingComm] [1652388177.401848][3628:3633] CHIP:DMG: ICR moving to [AddedComma] [1652388177.401990][3628:3633] CHIP:IN: Prepared secure message 0xaaaad07755f8 to 0x0000000000000002 (1) of type 0x8 and protocolId (0, 1) on exchange 37966i with MessageCounter:6596827. [1652388177.402131][3628:3633] CHIP:IN: Sending encrypted msg 0xaaaad07755f8 with MessageCounter:6596827 to 0x0000000000000002 (1) at monotonic time: 00000000013B2488 msec [1652388177.402323][3628:3633] CHIP:DMG: ICR moving to [CommandSen] [1652388177.498029][3628:3633] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:3236845303 on exchange 37965i [1652388177.498146][3628:3633] CHIP:EM: Found matching exchange: 37965i, Delegate: (nil) [1652388177.498225][3628:3633] CHIP:EM: Rxd Ack; Removing MessageCounter:2507241900 from Retrans Table on exchange 37965i [1652388177.498272][3628:3633] CHIP:EM: Removed CHIP MessageCounter:2507241900 from RetransTable on exchange 37965i [1652388177.634377][3628:3633] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:1124055 on exchange 37966i [1652388177.634460][3628:3633] CHIP:EM: Found matching exchange: 37966i, Delegate: 0xffff980065b0 [1652388177.634535][3628:3633] CHIP:EM: Rxd Ack; Removing MessageCounter:6596827 from Retrans Table on exchange 37966i [1652388177.634643][3628:3633] CHIP:EM: Removed CHIP MessageCounter:6596827 from RetransTable on exchange 37966i [1652388177.634760][3628:3633] CHIP:DMG: ICR moving to [ResponseRe] [1652388177.634882][3628:3633] CHIP:DMG: InvokeResponseMessage = [1652388177.634932][3628:3633] CHIP:DMG: { [1652388177.634977][3628:3633] CHIP:DMG: suppressResponse = false, [1652388177.635123][3628:3633] CHIP:DMG: InvokeResponseIBs = [1652388177.635268][3628:3633] CHIP:DMG: [ [1652388177.635319][3628:3633] CHIP:DMG: InvokeResponseIB = [1652388177.635387][3628:3633] CHIP:DMG: { [1652388177.635442][3628:3633] CHIP:DMG: CommandStatusIB = [1652388177.635508][3628:3633] CHIP:DMG: { [1652388177.635568][3628:3633] CHIP:DMG: CommandPathIB = [1652388177.635633][3628:3633] CHIP:DMG: { [1652388177.635705][3628:3633] CHIP:DMG: EndpointId = 0x0, [1652388177.635776][3628:3633] CHIP:DMG: ClusterId = 0x2a, [1652388177.635845][3628:3633] CHIP:DMG: CommandId = 0x0, [1652388177.635909][3628:3633] CHIP:DMG: }, [1652388177.635982][3628:3633] CHIP:DMG: [1652388177.636040][3628:3633] CHIP:DMG: StatusIB = [1652388177.636105][3628:3633] CHIP:DMG: { [1652388177.636170][3628:3633] CHIP:DMG: status = 0x00 (SUCCESS), [1652388177.636235][3628:3633] CHIP:DMG: }, [1652388177.636300][3628:3633] CHIP:DMG: [1652388177.636357][3628:3633] CHIP:DMG: }, [1652388177.636430][3628:3633] CHIP:DMG: [1652388177.636481][3628:3633] CHIP:DMG: }, [1652388177.636692][3628:3633] CHIP:DMG: [1652388177.636743][3628:3633] CHIP:DMG: ], [1652388177.636802][3628:3633] CHIP:DMG: [1652388177.636848][3628:3633] CHIP:DMG: InteractionModelRevision = 1 [1652388177.636893][3628:3633] CHIP:DMG: }, [1652388177.637008][3628:3633] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_002A Command=0x0000_0000 Status=0x0 [1652388177.637088][3628:3633] CHIP:DMG: ICR moving to [AwaitingDe] [1652388177.637181][3628:3633] CHIP:EM: Sending Standalone Ack for MessageCounter:1124055 on exchange 37966i [1652388177.637304][3628:3633] CHIP:IN: Prepared secure message 0xffffad2c29e8 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 37966i with MessageCounter:6596828. [1652388177.637376][3628:3633] CHIP:IN: Sending encrypted msg 0xffffad2c29e8 with MessageCounter:6596828 to 0x0000000000000002 (1) at monotonic time: 00000000013B2573 msec [1652388177.637592][3628:3633] CHIP:EM: Flushed pending ack for MessageCounter:1124055 on exchange 37966i [1652388177.637918][3628:3628] CHIP:CTL: Shutting down the commissioner [1652388177.638205][3628:3628] CHIP:CTL: Shutting down the controller [1652388177.638294][3628:3628] CHIP:CTL: Shutting down the commissioner [1652388177.638409][3628:3628] CHIP:CTL: Shutting down the controller [1652388177.638459][3628:3628] CHIP:IN: Expiring all connections for fabric 1!! [1652388177.638529][3628:3628] CHIP:CTL: Shutting down the commissioner [1652388177.638642][3628:3628] CHIP:CTL: Shutting down the controller [1652388177.638678][3628:3628] CHIP:IN: Expiring all connections for fabric 2!! [1652388177.638730][3628:3628] CHIP:CTL: Shutting down the commissioner [1652388177.638838][3628:3628] CHIP:CTL: Shutting down the controller [1652388177.638872][3628:3628] CHIP:IN: Expiring all connections for fabric 3!! [1652388177.638917][3628:3628] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1652388177.639517][3628:3628] CHIP:DMG: IM WH moving to [Uninitialized] [1652388177.639557][3628:3628] CHIP:DMG: IM WH moving to [Uninitialized] [1652388177.639587][3628:3628] CHIP:DMG: IM WH moving to [Uninitialized] [1652388177.639615][3628:3628] CHIP:DMG: IM WH moving to [Uninitialized] [1652388177.639647][3628:3628] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388177.639754][3628:3628] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1652388177.640041][3628:3628] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-7RQaIv) [1652388177.640805][3628:3628] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388177.640883][3628:3628] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1652388177.640921][3628:3628] CHIP:DL: Inet Layer shutdown [1652388177.640954][3628:3628] CHIP:DL: BLE shutdown [1652388177.640985][3628:3628] CHIP:DL: System Layer shutdown