[1699002737.773106][36264:36264] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1699002737.782035][36264:36264] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1699002737.782101][36264:36264] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1699002737.805202][36264:36264] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1699002737.806315][36264:36264] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1699002737.807059][36264:36264] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1699002737.807970][36264:36264] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-wvoe4s) [1699002737.808612][36264:36264] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1699002737.808703][36264:36264] CHIP:DL: NVS set: chip-counters/reboot-count = 55 (0x37) [1699002737.814222][36264:36264] CHIP:DL: Got Ethernet interface: eth0 [1699002737.816818][36264:36264] CHIP:DL: Found the primary Ethernet interface:eth0 [1699002737.821261][36264:36264] CHIP:DL: Got WiFi interface: wlan0 [1699002737.821347][36264:36264] CHIP:DL: Failed to reset WiFi statistic counts [1699002737.821621][36264:36264] CHIP:IN: UDP::Init bind&listen port=0 [1699002737.824573][36264:36264] CHIP:IN: UDP::Init bound to port=45113 [1699002737.824647][36264:36264] CHIP:IN: UDP::Init bind&listen port=0 [1699002737.824802][36264:36264] CHIP:IN: UDP::Init bound to port=38211 [1699002737.824837][36264:36264] CHIP:IN: BLEBase::Init - setting/overriding transport [1699002737.824862][36264:36264] CHIP:IN: TransportMgr initialized [1699002737.825130][36264:36264] CHIP:FP: Initializing FabricTable from persistent storage [1699002737.835119][36264:36264] CHIP:TS: Last Known Good Time: 2023-10-27T14:25:19 [1699002737.849919][36264:36264] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x027FBA21A63140CE, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1699002737.861389][36264:36264] CHIP:ZCL: Using ZAP configuration... [1699002737.898593][36264:36264] CHIP:CTL: System State Initialized... [1699002737.918270][36264:36264] CHIP:CTL: Setting attestation nonce to random value [1699002737.921980][36264:36264] CHIP:CTL: Setting CSR nonce to random value [1699002737.922254][36264:36264] CHIP:IN: UDP::Init bind&listen port=5550 [1699002737.922465][36264:36264] CHIP:IN: UDP::Init bound to port=5550 [1699002737.922520][36264:36264] CHIP:IN: UDP::Init bind&listen port=5550 [1699002737.922673][36264:36264] CHIP:IN: UDP::Init bound to port=5550 [1699002737.922711][36264:36264] CHIP:IN: TransportMgr initialized [1699002737.923654][36264:36267] CHIP:DL: CHIP task running [1699002737.924568][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1699002737.926103][36264:36267] CHIP:CTL: Setting attestation nonce to random value [1699002737.926614][36264:36267] CHIP:CTL: Setting CSR nonce to random value [1699002737.942671][36264:36267] CHIP:CTL: Generating NOC [1699002737.958913][36264:36267] CHIP:FP: Validating NOC chain [1699002737.966932][36264:36267] CHIP:FP: NOC chain validation successful [1699002737.967907][36264:36267] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1699002737.967976][36264:36267] CHIP:TS: Last Known Good Time: 2023-10-27T14:25:19 [1699002737.967999][36264:36267] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1699002737.968016][36264:36267] CHIP:TS: Retaining current Last Known Good Time [1699002737.976168][36264:36267] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1699002737.979680][36264:36267] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-27T14:25:19 [1699002737.982885][36264:36267] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 027FBA21A63140CE) [1699002737.982989][36264:36267] CHIP:IN: UDP::Init bind&listen port=5550 [1699002737.983129][36264:36267] CHIP:IN: UDP::Init bound to port=5550 [1699002737.983164][36264:36267] CHIP:IN: UDP::Init bind&listen port=5550 [1699002737.983259][36264:36267] CHIP:IN: UDP::Init bound to port=5550 [1699002737.983280][36264:36267] CHIP:IN: TransportMgr initialized [1699002738.031039][36264:36267] CHIP:CTL: Setting wifi credentials from parameters [1699002738.031093][36264:36267] CHIP:CTL: Setting attestation nonce to random value [1699002738.031168][36264:36267] CHIP:CTL: Setting CSR nonce to random value [1699002738.031220][36264:36267] CHIP:CTL: Commission called for node ID 0x00000000000007CE [1699002738.031268][36264:36267] CHIP:DL: Long dispatch time: 107 ms, for event type 2 [1699002738.040530][36264:36266] CHIP:DL: TRACE: Bus acquired for name C-8da8 [1699002738.061796][36264:36267] CHIP:DL: PlatformBlueZInit init success [1699002738.070116][36264:36266] CHIP:BLE: BLE removing known devices. [1699002738.072244][36264:36266] CHIP:BLE: BLE initiating scan. [1699002738.085008][36264:36266] CHIP:BLE: Device 4C:87:E4:A8:01:00 does not look like a CHIP device. [1699002738.101581][36264:36266] CHIP:BLE: Device CE:FC:11:82:4D:F3 does not look like a CHIP device. [1699002738.142176][36264:36266] CHIP:BLE: Device 34:DC:92:C1:B7:24 does not look like a CHIP device. [1699002738.179972][36264:36266] CHIP:BLE: New device scanned: C0:E5:C6:B3:50:8D [1699002738.238463][36264:36266] CHIP:BLE: Device 4E:D6:F8:43:03:7D does not look like a CHIP device. [1699002738.256829][36264:36266] CHIP:BLE: Device 42:BA:23:DF:C0:C0 does not look like a CHIP device. [1699002738.258673][36264:36266] CHIP:BLE: Device 5E:39:A0:74:A8:A4 does not look like a CHIP device. [1699002738.300133][36264:36266] CHIP:BLE: Device 66:9E:E2:8D:51:99 does not look like a CHIP device. [1699002738.303228][36264:36266] CHIP:BLE: Device 18:EE:69:17:4C:9A does not look like a CHIP device. [1699002738.316423][36264:36266] CHIP:BLE: New device scanned: E4:5F:01:C2:47:B0 [1699002738.316483][36264:36266] CHIP:BLE: Device discriminator match. Attempting to connect. [1699002742.305688][36264:36266] CHIP:DL: ConnectDevice complete [1699002743.737824][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0008 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.737880][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0008 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.737906][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0012 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.737923][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0012 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.737942][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0008 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.737957][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0008 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.737980][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.738002][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0008 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.738017][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0008 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.738036][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.738053][36264:36266] CHIP:DL: Char /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 on service /org/bluez/hci0/dev_E4_5F_01_C2_47_B0/service0015 [1699002743.738096][36264:36266] CHIP:DL: New BLE connection: conn 0xffffa861a650, device E4:5F:01:C2:47:B0, path /org/bluez/hci0/dev_E4_5F_01_C2_47_B0 [1699002743.738287][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16385 [1699002743.738329][36264:36267] CHIP:DIS: Closing all BLE connections [1699002743.738514][36264:36267] CHIP:IN: BleConnectionComplete: endPoint 0xaaaac8402480 [1699002743.741777][36264:36267] CHIP:IN: SecureSession[0xffffa32e2300]: Allocated Type:1 LSID:3193 [1699002743.741874][36264:36267] CHIP:SC: Assigned local session key ID 3193 [1699002743.748067][36264:36267] CHIP:EM: <<< [E:26208i S:0 M:82986291] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1699002743.748154][36264:36267] CHIP:IN: Message appended to BLE send queue [1699002743.748183][36264:36267] CHIP:SC: Sent PBKDF param request [1699002744.057919][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002744.154998][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1699002744.155052][36264:36267] CHIP:BLE: subscribe complete, ep = 0xaaaac8402480 [1699002744.155453][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002744.155604][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002744.156581][36264:36267] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1699002744.156621][36264:36267] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1699002744.156636][36264:36267] CHIP:BLE: local and remote recv window size = 6 [1699002744.157273][36264:36267] CHIP:IN: BLE EndPoint 0xaaaac8402480 Connection Complete [1699002744.253335][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002744.256394][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002744.256774][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002744.258177][36264:36267] CHIP:EM: >>> [E:26208i S:0 M:211636709] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1699002744.258280][36264:36267] CHIP:EM: Found matching exchange: 26208i, Delegate: 0xffffa72564d0 [1699002744.258452][36264:36267] CHIP:SC: Received PBKDF param response [1699002744.261189][36264:36267] CHIP:SC: Peer assigned session ID 27946 [1699002744.294958][36264:36267] CHIP:EM: <<< [E:26208i S:0 M:82986292] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1699002744.295767][36264:36267] CHIP:SC: Sent spake2p msg1 [1699002744.350828][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002744.353812][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002744.354233][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002744.354735][36264:36267] CHIP:EM: >>> [E:26208i S:0 M:211636710] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1699002744.354829][36264:36267] CHIP:EM: Found matching exchange: 26208i, Delegate: 0xffffa72564d0 [1699002744.354967][36264:36267] CHIP:SC: Received spake2p msg2 [1699002744.359790][36264:36267] CHIP:EM: <<< [E:26208i S:0 M:82986293] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1699002744.361767][36264:36267] CHIP:SC: Sent spake2p msg3 [1699002744.448285][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002744.449690][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002744.450433][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002744.450885][36264:36267] CHIP:EM: >>> [E:26208i S:0 M:211636711] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1699002744.450982][36264:36267] CHIP:EM: Found matching exchange: 26208i, Delegate: 0xffffa72564d0 [1699002744.452182][36264:36267] CHIP:SC: SecureSession[0xffffa32e2300, LSID:3193]: State change 'kEstablishing' --> 'kActive' [1699002744.452336][36264:36267] CHIP:IN: SecureSession[0xffffa32e2300]: Activated - Type:1 LSID:3193 [1699002744.452383][36264:36267] CHIP:IN: New secure session activated for device , LSID:3193 PSID:27946! [1699002744.452451][36264:36267] CHIP:CTL: Remote device completed SPAKE2+ handshake [1699002744.452501][36264:36267] CHIP:TOO: Pairing Success [1699002744.452540][36264:36267] CHIP:TOO: PASE establishment successful [1699002744.458885][36264:36267] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1699002744.462625][36264:36267] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1699002744.462681][36264:36267] CHIP:CTL: Sending read request for commissioning information [1699002744.466047][36264:36267] CHIP:DMG: SendReadRequest ReadClient[0xffffa0e17180]: Sending Read Request [1699002744.470483][36264:36267] CHIP:EM: <<< [E:26209i S:3193 M:120084037] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest) [1699002744.471692][36264:36267] CHIP:DMG: MoveToState ReadClient[0xffffa0e17180]: Moving to [AwaitingIn] [1699002744.545854][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002744.549692][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002744.550097][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002744.644116][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002744.644580][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002744.645115][36264:36267] CHIP:EM: >>> [E:26209i S:3193 M:186828885] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1699002744.645215][36264:36267] CHIP:EM: Found matching exchange: 26209i, Delegate: 0xffffa0e17190 [1699002744.649856][36264:36267] CHIP:DMG: ReportDataMessage = [1699002744.650022][36264:36267] CHIP:DMG: { [1699002744.650151][36264:36267] CHIP:DMG: AttributeReportIBs = [1699002744.650266][36264:36267] CHIP:DMG: [ [1699002744.650315][36264:36267] CHIP:DMG: AttributeReportIB = [1699002744.650408][36264:36267] CHIP:DMG: { [1699002744.652754][36264:36267] CHIP:DMG: AttributeDataIB = [1699002744.652881][36264:36267] CHIP:DMG: { [1699002744.652919][36264:36267] CHIP:DMG: DataVersion = 0xc1379394, [1699002744.652940][36264:36267] CHIP:DMG: AttributePathIB = [1699002744.652964][36264:36267] CHIP:DMG: { [1699002744.653071][36264:36267] CHIP:DMG: Endpoint = 0x0, [1699002744.653099][36264:36267] CHIP:DMG: Cluster = 0x31, [1699002744.653128][36264:36267] CHIP:DMG: Attribute = 0x0000_0003, [1699002744.653145][36264:36267] CHIP:DMG: } [1699002744.653179][36264:36267] CHIP:DMG: [1699002744.653212][36264:36267] CHIP:DMG: Data = 20, [1699002744.653229][36264:36267] CHIP:DMG: }, [1699002744.653262][36264:36267] CHIP:DMG: [1699002744.653279][36264:36267] CHIP:DMG: }, [1699002744.653330][36264:36267] CHIP:DMG: [1699002744.653349][36264:36267] CHIP:DMG: AttributeReportIB = [1699002744.653383][36264:36267] CHIP:DMG: { [1699002744.653401][36264:36267] CHIP:DMG: AttributeDataIB = [1699002744.653421][36264:36267] CHIP:DMG: { [1699002744.653447][36264:36267] CHIP:DMG: DataVersion = 0xc1b9d1bd, [1699002744.653465][36264:36267] CHIP:DMG: AttributePathIB = [1699002744.653485][36264:36267] CHIP:DMG: { [1699002744.653508][36264:36267] CHIP:DMG: Endpoint = 0x0, [1699002744.653529][36264:36267] CHIP:DMG: Cluster = 0x28, [1699002744.653550][36264:36267] CHIP:DMG: Attribute = 0x0000_0004, [1699002744.653568][36264:36267] CHIP:DMG: } [1699002744.653593][36264:36267] CHIP:DMG: [1699002744.653616][36264:36267] CHIP:DMG: Data = 32769, [1699002744.653632][36264:36267] CHIP:DMG: }, [1699002744.653660][36264:36267] CHIP:DMG: [1699002744.653677][36264:36267] CHIP:DMG: }, [1699002744.653719][36264:36267] CHIP:DMG: [1699002744.653738][36264:36267] CHIP:DMG: AttributeReportIB = [1699002744.653768][36264:36267] CHIP:DMG: { [1699002744.653785][36264:36267] CHIP:DMG: AttributeDataIB = [1699002744.653806][36264:36267] CHIP:DMG: { [1699002744.653828][36264:36267] CHIP:DMG: DataVersion = 0xc1b9d1bd, [1699002744.653844][36264:36267] CHIP:DMG: AttributePathIB = [1699002744.653866][36264:36267] CHIP:DMG: { [1699002744.653886][36264:36267] CHIP:DMG: Endpoint = 0x0, [1699002744.653907][36264:36267] CHIP:DMG: Cluster = 0x28, [1699002744.653928][36264:36267] CHIP:DMG: Attribute = 0x0000_0002, [1699002744.653945][36264:36267] CHIP:DMG: } [1699002744.653968][36264:36267] CHIP:DMG: [1699002744.653990][36264:36267] CHIP:DMG: Data = 65521, [1699002744.654008][36264:36267] CHIP:DMG: }, [1699002744.654033][36264:36267] CHIP:DMG: [1699002744.654050][36264:36267] CHIP:DMG: }, [1699002744.654090][36264:36267] CHIP:DMG: [1699002744.654107][36264:36267] CHIP:DMG: AttributeReportIB = [1699002744.654142][36264:36267] CHIP:DMG: { [1699002744.654164][36264:36267] CHIP:DMG: AttributeDataIB = [1699002744.654185][36264:36267] CHIP:DMG: { [1699002744.654208][36264:36267] CHIP:DMG: DataVersion = 0xd0fd56f7, [1699002744.654225][36264:36267] CHIP:DMG: AttributePathIB = [1699002744.654245][36264:36267] CHIP:DMG: { [1699002744.654269][36264:36267] CHIP:DMG: Endpoint = 0x0, [1699002744.654290][36264:36267] CHIP:DMG: Cluster = 0x30, [1699002744.654311][36264:36267] CHIP:DMG: Attribute = 0x0000_0003, [1699002744.654327][36264:36267] CHIP:DMG: } [1699002744.654353][36264:36267] CHIP:DMG: [1699002744.654379][36264:36267] CHIP:DMG: Data = 2, [1699002744.654395][36264:36267] CHIP:DMG: }, [1699002744.654422][36264:36267] CHIP:DMG: [1699002744.654439][36264:36267] CHIP:DMG: }, [1699002744.654481][36264:36267] CHIP:DMG: [1699002744.654500][36264:36267] CHIP:DMG: AttributeReportIB = [1699002744.654531][36264:36267] CHIP:DMG: { [1699002744.654548][36264:36267] CHIP:DMG: AttributeDataIB = [1699002744.654569][36264:36267] CHIP:DMG: { [1699002744.654592][36264:36267] CHIP:DMG: DataVersion = 0xd0fd56f7, [1699002744.654608][36264:36267] CHIP:DMG: AttributePathIB = [1699002744.654629][36264:36267] CHIP:DMG: { [1699002744.654651][36264:36267] CHIP:DMG: Endpoint = 0x0, [1699002744.654671][36264:36267] CHIP:DMG: Cluster = 0x30, [1699002744.654691][36264:36267] CHIP:DMG: Attribute = 0x0000_0002, [1699002744.654709][36264:36267] CHIP:DMG: } [1699002744.654734][36264:36267] CHIP:DMG: [1699002744.654756][36264:36267] CHIP:DMG: Data = 0, [1699002744.654774][36264:36267] CHIP:DMG: }, [1699002744.654801][36264:36267] CHIP:DMG: [1699002744.654817][36264:36267] CHIP:DMG: }, [1699002744.654860][36264:36267] CHIP:DMG: [1699002744.654880][36264:36267] CHIP:DMG: AttributeReportIB = [1699002744.654913][36264:36267] CHIP:DMG: { [1699002744.654932][36264:36267] CHIP:DMG: AttributeDataIB = [1699002744.654951][36264:36267] CHIP:DMG: { [1699002744.654973][36264:36267] CHIP:DMG: DataVersion = 0xd0fd56f7, [1699002744.654991][36264:36267] CHIP:DMG: AttributePathIB = [1699002744.655011][36264:36267] CHIP:DMG: { [1699002744.655032][36264:36267] CHIP:DMG: Endpoint = 0x0, [1699002744.655054][36264:36267] CHIP:DMG: Cluster = 0x30, [1699002744.655074][36264:36267] CHIP:DMG: Attribute = 0x0000_0001, [1699002744.655091][36264:36267] CHIP:DMG: } [1699002744.655114][36264:36267] CHIP:DMG: [1699002744.655135][36264:36267] CHIP:DMG: Data = [1699002744.655156][36264:36267] CHIP:DMG: { [1699002744.655179][36264:36267] CHIP:DMG: 0x0 = 60, [1699002744.655201][36264:36267] CHIP:DMG: 0x1 = 900, [1699002744.655223][36264:36267] CHIP:DMG: }, [1699002744.655239][36264:36267] CHIP:DMG: }, [1699002744.655268][36264:36267] CHIP:DMG: [1699002744.655285][36264:36267] CHIP:DMG: }, [1699002744.655329][36264:36267] CHIP:DMG: [1699002744.655346][36264:36267] CHIP:DMG: AttributeReportIB = [1699002744.655377][36264:36267] CHIP:DMG: { [1699002744.655394][36264:36267] CHIP:DMG: AttributeDataIB = [1699002744.655413][36264:36267] CHIP:DMG: { [1699002744.655435][36264:36267] CHIP:DMG: DataVersion = 0xd0fd56f7, [1699002744.655452][36264:36267] CHIP:DMG: AttributePathIB = [1699002744.655471][36264:36267] CHIP:DMG: { [1699002744.655492][36264:36267] CHIP:DMG: Endpoint = 0x0, [1699002744.655514][36264:36267] CHIP:DMG: Cluster = 0x30, [1699002744.655535][36264:36267] CHIP:DMG: Attribute = 0x0000_0000, [1699002744.655551][36264:36267] CHIP:DMG: } [1699002744.655575][36264:36267] CHIP:DMG: [1699002744.655598][36264:36267] CHIP:DMG: Data = 0, [1699002744.655614][36264:36267] CHIP:DMG: }, [1699002744.655643][36264:36267] CHIP:DMG: [1699002744.655659][36264:36267] CHIP:DMG: }, [1699002744.655700][36264:36267] CHIP:DMG: [1699002744.655717][36264:36267] CHIP:DMG: AttributeReportIB = [1699002744.655748][36264:36267] CHIP:DMG: { [1699002744.655765][36264:36267] CHIP:DMG: AttributeDataIB = [1699002744.655785][36264:36267] CHIP:DMG: { [1699002744.655808][36264:36267] CHIP:DMG: DataVersion = 0xc1379394, [1699002744.655825][36264:36267] CHIP:DMG: AttributePathIB = [1699002744.655845][36264:36267] CHIP:DMG: { [1699002744.655866][36264:36267] CHIP:DMG: Endpoint = 0x0, [1699002744.655887][36264:36267] CHIP:DMG: Cluster = 0x31, [1699002744.655908][36264:36267] CHIP:DMG: Attribute = 0x0000_FFFC, [1699002744.655925][36264:36267] CHIP:DMG: } [1699002744.655950][36264:36267] CHIP:DMG: [1699002744.655973][36264:36267] CHIP:DMG: Data = 1, [1699002744.655988][36264:36267] CHIP:DMG: }, [1699002744.656015][36264:36267] CHIP:DMG: [1699002744.656031][36264:36267] CHIP:DMG: }, [1699002744.656058][36264:36267] CHIP:DMG: [1699002744.656074][36264:36267] CHIP:DMG: ], [1699002744.656177][36264:36267] CHIP:DMG: [1699002744.656266][36264:36267] CHIP:DMG: SuppressResponse = true, [1699002744.656301][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002744.656317][36264:36267] CHIP:DMG: } [1699002744.673133][36264:36267] CHIP:CTL: ----- NetworkCommissioning Features: has WiFi. endpointid = 0 [1699002744.674287][36264:36267] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1699002744.674447][36264:36267] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ReadCommissioningInfo2' [1699002744.674531][36264:36267] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo2' [1699002744.674697][36264:36267] CHIP:DMG: SendReadRequest ReadClient[0xffffa0e16e00]: Sending Read Request [1699002744.675339][36264:36267] CHIP:EM: <<< [E:26210i S:3193 M:120084038] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest) [1699002744.676917][36264:36267] CHIP:DMG: MoveToState ReadClient[0xffffa0e16e00]: Moving to [AwaitingIn] [1699002744.741046][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002744.743014][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002744.743394][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002744.744002][36264:36267] CHIP:EM: >>> [E:26210i S:3193 M:186828886] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1699002744.744109][36264:36267] CHIP:EM: Found matching exchange: 26210i, Delegate: 0xffffa0e16e10 [1699002744.744409][36264:36267] CHIP:DMG: ReportDataMessage = [1699002744.744491][36264:36267] CHIP:DMG: { [1699002744.744542][36264:36267] CHIP:DMG: AttributeReportIBs = [1699002744.744631][36264:36267] CHIP:DMG: [ [1699002744.744680][36264:36267] CHIP:DMG: AttributeReportIB = [1699002744.744763][36264:36267] CHIP:DMG: { [1699002744.744810][36264:36267] CHIP:DMG: AttributeDataIB = [1699002744.744862][36264:36267] CHIP:DMG: { [1699002744.745051][36264:36267] CHIP:DMG: DataVersion = 0xd0fd56f7, [1699002744.745107][36264:36267] CHIP:DMG: AttributePathIB = [1699002744.745164][36264:36267] CHIP:DMG: { [1699002744.745226][36264:36267] CHIP:DMG: Endpoint = 0x0, [1699002744.745280][36264:36267] CHIP:DMG: Cluster = 0x30, [1699002744.745336][36264:36267] CHIP:DMG: Attribute = 0x0000_0004, [1699002744.745377][36264:36267] CHIP:DMG: } [1699002744.745441][36264:36267] CHIP:DMG: [1699002744.745505][36264:36267] CHIP:DMG: Data = false, [1699002744.745546][36264:36267] CHIP:DMG: }, [1699002744.745614][36264:36267] CHIP:DMG: [1699002744.745659][36264:36267] CHIP:DMG: }, [1699002744.745729][36264:36267] CHIP:DMG: [1699002744.745768][36264:36267] CHIP:DMG: ], [1699002744.745846][36264:36267] CHIP:DMG: [1699002744.745904][36264:36267] CHIP:DMG: SuppressResponse = true, [1699002744.745950][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002744.745992][36264:36267] CHIP:DMG: } [1699002744.747048][36264:36267] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo2' [1699002744.747198][36264:36267] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo2' -> 'ArmFailSafe' [1699002744.747352][36264:36267] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1699002744.747434][36264:36267] CHIP:CTL: Arming failsafe (60 seconds) [1699002744.748404][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002744.748599][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002744.749304][36264:36267] CHIP:EM: <<< [E:26211i S:3193 M:120084039] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002744.750580][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002744.838374][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002744.840514][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002744.840904][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002744.841460][36264:36267] CHIP:EM: >>> [E:26211i S:3193 M:186828887] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002744.841560][36264:36267] CHIP:EM: Found matching exchange: 26211i, Delegate: 0xffffa0e16c48 [1699002744.841671][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002744.841878][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002744.841946][36264:36267] CHIP:DMG: { [1699002744.842020][36264:36267] CHIP:DMG: suppressResponse = false, [1699002744.842065][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002744.842172][36264:36267] CHIP:DMG: [ [1699002744.842230][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002744.842314][36264:36267] CHIP:DMG: { [1699002744.842363][36264:36267] CHIP:DMG: CommandDataIB = [1699002744.842415][36264:36267] CHIP:DMG: { [1699002744.842461][36264:36267] CHIP:DMG: CommandPathIB = [1699002744.842514][36264:36267] CHIP:DMG: { [1699002744.842601][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002744.842654][36264:36267] CHIP:DMG: ClusterId = 0x30, [1699002744.842702][36264:36267] CHIP:DMG: CommandId = 0x1, [1699002744.842748][36264:36267] CHIP:DMG: }, [1699002744.842810][36264:36267] CHIP:DMG: [1699002744.842856][36264:36267] CHIP:DMG: CommandFields = [1699002744.842910][36264:36267] CHIP:DMG: { [1699002744.842967][36264:36267] CHIP:DMG: 0x0 = 0, [1699002744.843030][36264:36267] CHIP:DMG: 0x1 = "" (0 chars), [1699002744.843093][36264:36267] CHIP:DMG: }, [1699002744.843134][36264:36267] CHIP:DMG: }, [1699002744.843295][36264:36267] CHIP:DMG: [1699002744.843351][36264:36267] CHIP:DMG: }, [1699002744.843431][36264:36267] CHIP:DMG: [1699002744.843476][36264:36267] CHIP:DMG: ], [1699002744.843559][36264:36267] CHIP:DMG: [1699002744.843612][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002744.843649][36264:36267] CHIP:DMG: }, [1699002744.843927][36264:36267] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1699002744.848197][36264:36267] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1699002744.848357][36264:36267] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1699002744.848409][36264:36267] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1699002744.848491][36264:36267] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1699002744.848537][36264:36267] CHIP:CTL: Setting Regulatory Config [1699002744.848578][36264:36267] CHIP:CTL: No regulatory config supplied by controller, leaving as device default (0) [1699002744.848882][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002744.849110][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002744.849572][36264:36267] CHIP:EM: <<< [E:26212i S:3193 M:120084040] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002744.850402][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002744.850568][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002744.936097][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002744.937981][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002744.938362][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002744.938920][36264:36267] CHIP:EM: >>> [E:26212i S:3193 M:186828888] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002744.939021][36264:36267] CHIP:EM: Found matching exchange: 26212i, Delegate: 0xffffa0e16a88 [1699002744.939132][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002744.939308][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002744.939378][36264:36267] CHIP:DMG: { [1699002744.939440][36264:36267] CHIP:DMG: suppressResponse = false, [1699002744.939484][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002744.939575][36264:36267] CHIP:DMG: [ [1699002744.939622][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002744.939712][36264:36267] CHIP:DMG: { [1699002744.939760][36264:36267] CHIP:DMG: CommandDataIB = [1699002744.939816][36264:36267] CHIP:DMG: { [1699002744.939863][36264:36267] CHIP:DMG: CommandPathIB = [1699002744.939919][36264:36267] CHIP:DMG: { [1699002744.939978][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002744.940036][36264:36267] CHIP:DMG: ClusterId = 0x30, [1699002744.940088][36264:36267] CHIP:DMG: CommandId = 0x3, [1699002744.940130][36264:36267] CHIP:DMG: }, [1699002744.940197][36264:36267] CHIP:DMG: [1699002744.940301][36264:36267] CHIP:DMG: CommandFields = [1699002744.940358][36264:36267] CHIP:DMG: { [1699002744.940424][36264:36267] CHIP:DMG: 0x0 = 0, [1699002744.940488][36264:36267] CHIP:DMG: 0x1 = "" (0 chars), [1699002744.940542][36264:36267] CHIP:DMG: }, [1699002744.940587][36264:36267] CHIP:DMG: }, [1699002744.940659][36264:36267] CHIP:DMG: [1699002744.940700][36264:36267] CHIP:DMG: }, [1699002744.940774][36264:36267] CHIP:DMG: [1699002744.940818][36264:36267] CHIP:DMG: ], [1699002744.940902][36264:36267] CHIP:DMG: [1699002744.940955][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002744.940992][36264:36267] CHIP:DMG: }, [1699002744.941251][36264:36267] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1699002744.941427][36264:36267] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0 [1699002744.941515][36264:36267] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1699002744.941564][36264:36267] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1699002744.941646][36264:36267] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1699002744.941691][36264:36267] CHIP:CTL: Sending request for PAI certificate [1699002744.941800][36264:36267] CHIP:CTL: Sending Certificate Chain request to 0xffffa7256480 device [1699002744.942086][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002744.948376][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002744.948803][36264:36267] CHIP:EM: <<< [E:26213i S:3193 M:120084041] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002744.949568][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002744.949739][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002745.033439][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002745.037221][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002745.037619][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002745.134428][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002745.134845][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002745.228580][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002745.228848][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002745.229219][36264:36267] CHIP:EM: >>> [E:26213i S:3193 M:186828889] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002745.229291][36264:36267] CHIP:EM: Found matching exchange: 26213i, Delegate: 0xffffa0e168c8 [1699002745.229361][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002745.229478][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002745.229514][36264:36267] CHIP:DMG: { [1699002745.229545][36264:36267] CHIP:DMG: suppressResponse = false, [1699002745.229567][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002745.229616][36264:36267] CHIP:DMG: [ [1699002745.229639][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002745.229685][36264:36267] CHIP:DMG: { [1699002745.229708][36264:36267] CHIP:DMG: CommandDataIB = [1699002745.229737][36264:36267] CHIP:DMG: { [1699002745.229761][36264:36267] CHIP:DMG: CommandPathIB = [1699002745.229797][36264:36267] CHIP:DMG: { [1699002745.229832][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002745.229863][36264:36267] CHIP:DMG: ClusterId = 0x3e, [1699002745.229891][36264:36267] CHIP:DMG: CommandId = 0x3, [1699002745.229911][36264:36267] CHIP:DMG: }, [1699002745.229944][36264:36267] CHIP:DMG: [1699002745.229970][36264:36267] CHIP:DMG: CommandFields = [1699002745.229998][36264:36267] CHIP:DMG: { [1699002745.230034][36264:36267] CHIP:DMG: 0x0 = [ [1699002745.230382][36264:36267] CHIP:DMG: 0x30, 0x82, 0x01, 0xcb, 0x30, 0x82, 0x01, 0x71, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x0f, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0x0c, 0x8c, 0x87, 0x6d, 0x03, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x05, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x09, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0x0b, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x06, 0x03, 0x55, 0x1d, 0x [1699002745.230421][36264:36267] CHIP:DMG: ] (463 bytes) [1699002745.230451][36264:36267] CHIP:DMG: }, [1699002745.230472][36264:36267] CHIP:DMG: }, [1699002745.230508][36264:36267] CHIP:DMG: [1699002745.230531][36264:36267] CHIP:DMG: }, [1699002745.230568][36264:36267] CHIP:DMG: [1699002745.230588][36264:36267] CHIP:DMG: ], [1699002745.230631][36264:36267] CHIP:DMG: [1699002745.230659][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002745.230678][36264:36267] CHIP:DMG: }, [1699002745.230824][36264:36267] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1699002745.231001][36264:36267] CHIP:CTL: Received certificate chain from the device [1699002745.231060][36264:36267] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest' [1699002745.231145][36264:36267] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' [1699002745.231207][36264:36267] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' [1699002745.231231][36264:36267] CHIP:CTL: Sending request for DAC certificate [1699002745.231253][36264:36267] CHIP:CTL: Sending Certificate Chain request to 0xffffa7256480 device [1699002745.231402][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002745.231499][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002745.231808][36264:36267] CHIP:EM: <<< [E:26214i S:3193 M:120084042] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002745.232739][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002745.232918][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002745.325944][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002745.329702][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002745.330060][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002745.426778][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002745.427187][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002745.571067][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002745.571485][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002745.571988][36264:36267] CHIP:EM: >>> [E:26214i S:3193 M:186828890] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002745.572088][36264:36267] CHIP:EM: Found matching exchange: 26214i, Delegate: 0xffffa0e16708 [1699002745.572342][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002745.572533][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002745.572598][36264:36267] CHIP:DMG: { [1699002745.572662][36264:36267] CHIP:DMG: suppressResponse = false, [1699002745.572705][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002745.572795][36264:36267] CHIP:DMG: [ [1699002745.572844][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002745.572925][36264:36267] CHIP:DMG: { [1699002745.572973][36264:36267] CHIP:DMG: CommandDataIB = [1699002745.573024][36264:36267] CHIP:DMG: { [1699002745.573071][36264:36267] CHIP:DMG: CommandPathIB = [1699002745.573127][36264:36267] CHIP:DMG: { [1699002745.573190][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002745.573244][36264:36267] CHIP:DMG: ClusterId = 0x3e, [1699002745.573297][36264:36267] CHIP:DMG: CommandId = 0x3, [1699002745.573339][36264:36267] CHIP:DMG: }, [1699002745.573400][36264:36267] CHIP:DMG: [1699002745.573450][36264:36267] CHIP:DMG: CommandFields = [1699002745.573501][36264:36267] CHIP:DMG: { [1699002745.573556][36264:36267] CHIP:DMG: 0x0 = [ [1699002745.574332][36264:36267] CHIP:DMG: 0x30, 0x82, 0x01, 0xe7, 0x30, 0x82, 0x01, 0x8e, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x69, 0xcd, 0xf1, 0x0d, 0xe9, 0xe5, 0x4e, 0xd1, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x44, 0x41, 0x43, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x2f, 0x30, 0x78, 0x38, 0x30, 0x30, 0x31, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x38, 0x30, 0x30, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x46, 0x3a, 0xc6, 0x93, 0x42, 0x91, 0x0a, 0x0e, 0x55, 0x88, 0xfc, 0x6f, 0xf5, 0x6b, 0xb6, 0x3e, 0x62, 0xec, 0xce, 0xcb, 0x14, 0x8f, 0x7d, 0x4e, 0xb0, 0x3e, 0xe5, 0x52, 0x60, 0x14, 0x15, 0x76, 0x7d, 0x16, 0xa5, 0xc6, 0x63, 0xf7, 0x93, 0x [1699002745.574416][36264:36267] CHIP:DMG: ] (491 bytes) [1699002745.574477][36264:36267] CHIP:DMG: }, [1699002745.574520][36264:36267] CHIP:DMG: }, [1699002745.574593][36264:36267] CHIP:DMG: [1699002745.574635][36264:36267] CHIP:DMG: }, [1699002745.574709][36264:36267] CHIP:DMG: [1699002745.574753][36264:36267] CHIP:DMG: ], [1699002745.574836][36264:36267] CHIP:DMG: [1699002745.574886][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002745.574924][36264:36267] CHIP:DMG: }, [1699002745.575181][36264:36267] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1699002745.575318][36264:36267] CHIP:CTL: Received certificate chain from the device [1699002745.575407][36264:36267] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest' [1699002745.575533][36264:36267] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' [1699002745.575625][36264:36267] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' [1699002745.575671][36264:36267] CHIP:CTL: Sending Attestation Request to the device. [1699002745.575760][36264:36267] CHIP:CTL: Sending Attestation request to 0xffffa7256480 device [1699002745.575984][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002745.576087][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002745.576687][36264:36267] CHIP:EM: <<< [E:26215i S:3193 M:120084043] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002745.578467][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002745.578585][36264:36267] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1699002745.578809][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002745.667562][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002745.671153][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002745.671559][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002745.766877][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002745.767118][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002745.865459][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002745.865844][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002745.866367][36264:36267] CHIP:EM: >>> [E:26215i S:3193 M:186828891] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002745.866470][36264:36267] CHIP:EM: Found matching exchange: 26215i, Delegate: 0xffffa0e16548 [1699002745.866590][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002745.866773][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002745.866839][36264:36267] CHIP:DMG: { [1699002745.866898][36264:36267] CHIP:DMG: suppressResponse = false, [1699002745.866941][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002745.867033][36264:36267] CHIP:DMG: [ [1699002745.867081][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002745.867165][36264:36267] CHIP:DMG: { [1699002745.867214][36264:36267] CHIP:DMG: CommandDataIB = [1699002745.867270][36264:36267] CHIP:DMG: { [1699002745.867319][36264:36267] CHIP:DMG: CommandPathIB = [1699002745.867374][36264:36267] CHIP:DMG: { [1699002745.867434][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002745.867487][36264:36267] CHIP:DMG: ClusterId = 0x3e, [1699002745.867540][36264:36267] CHIP:DMG: CommandId = 0x1, [1699002745.867582][36264:36267] CHIP:DMG: }, [1699002745.867642][36264:36267] CHIP:DMG: [1699002745.867692][36264:36267] CHIP:DMG: CommandFields = [1699002745.867743][36264:36267] CHIP:DMG: { [1699002745.867799][36264:36267] CHIP:DMG: 0x0 = [ [1699002745.868595][36264:36267] CHIP:DMG: 0x15, 0x31, 0x01, 0x1b, 0x02, 0x30, 0x82, 0x02, 0x17, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x02, 0xa0, 0x82, 0x02, 0x08, 0x30, 0x82, 0x02, 0x04, 0x02, 0x01, 0x03, 0x31, 0x0d, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x82, 0x01, 0x70, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x01, 0xa0, 0x82, 0x01, 0x61, 0x04, 0x82, 0x01, 0x5d, 0x15, 0x24, 0x00, 0x01, 0x25, 0x01, 0xf1, 0xff, 0x36, 0x02, 0x05, 0x00, 0x80, 0x05, 0x01, 0x80, 0x05, 0x02, 0x80, 0x05, 0x03, 0x80, 0x05, 0x04, 0x80, 0x05, 0x05, 0x80, 0x05, 0x06, 0x80, 0x05, 0x07, 0x80, 0x05, 0x08, 0x80, 0x05, 0x09, 0x80, 0x05, 0x0a, 0x80, 0x05, 0x0b, 0x80, 0x05, 0x0c, 0x80, 0x05, 0x0d, 0x80, 0x05, 0x0e, 0x80, 0x05, 0x0f, 0x80, 0x05, 0x10, 0x80, 0x05, 0x11, 0x80, 0x05, 0x12, 0x80, 0x05, 0x13, 0x80, 0x05, 0x14, 0x80, 0x05, 0x15, 0x80, 0x05, 0x16, 0x80, 0x05, 0x17, 0x80, 0x05, 0x18, 0x80, 0x05, 0x19, 0x80, 0x05, 0x1a, 0x80, 0x05, 0x1b, 0x80, 0x05, 0x1c, 0x80, 0x05, 0x1d, 0x80, 0x05, 0x1e, 0x80, 0x05, 0x1f, 0x80, 0x05, 0x20, 0x80, 0x05, 0x21, 0x80, 0x05, 0x22, 0x80, 0x05, 0x23, 0x80, 0x05, 0x24, 0x80, 0x05, 0x25, 0x80, 0x05, 0x26, 0x80, 0x05, 0x27, 0x80, 0x05, 0x28, 0x80, 0x05, 0x29, 0x80, 0x05, 0x2a, 0x80, 0x05, 0x2b, 0x80, 0x05, 0x2c, 0x80, 0x05, 0x2d, 0x80, 0x05, 0x2e, 0x80, 0x05, 0x2f, 0x80, 0x05, 0x30, 0x80, 0x05, 0x31, 0x80, 0x05, 0x32, 0x80, 0x05, 0x33, 0x80, 0x05, 0x34, 0x80, 0x05, 0x35, 0x80, 0x05, 0x36, 0x80, 0x05, 0x37, 0x80, 0x05, 0x38, 0x80, 0x05, 0x39, 0x80, 0x05, 0x3a, 0x80, 0x05, 0x3b, 0x80, 0x05, 0x3c, 0x80, 0x05, 0x3d, 0x80, 0x05, 0x3e, 0x80, 0x05, 0x3f, 0x80, 0x05, 0x40, 0x80, 0x05, 0x41, 0x80, 0x05, 0x42, 0x80, 0x05, 0x43, 0x80, 0x [1699002745.868689][36264:36267] CHIP:DMG: ] (583 bytes) [1699002745.868747][36264:36267] CHIP:DMG: 0x1 = [ [1699002745.868932][36264:36267] CHIP:DMG: 0x17, 0x27, 0xb0, 0x58, 0x08, 0x8c, 0x36, 0xb7, 0xaa, 0xdc, 0x41, 0x6f, 0x9a, 0xba, 0x97, 0xa8, 0x5a, 0xc0, 0xa0, 0xed, 0x8f, 0x05, 0xea, 0xc0, 0x18, 0x67, 0xd7, 0x6a, 0x09, 0xa7, 0x26, 0xe7, 0x85, 0xf8, 0xe9, 0x3b, 0x5f, 0x57, 0x20, 0x17, 0xc9, 0x27, 0x3a, 0xba, 0x88, 0x5d, 0xaf, 0xa1, 0x8a, 0x64, 0x94, 0xf4, 0x64, 0xca, 0xf3, 0x5d, 0x71, 0x69, 0x06, 0x7f, 0x1f, 0xa2, 0x4d, 0x0a, [1699002745.868992][36264:36267] CHIP:DMG: ] (64 bytes) [1699002745.869050][36264:36267] CHIP:DMG: }, [1699002745.869096][36264:36267] CHIP:DMG: }, [1699002745.869173][36264:36267] CHIP:DMG: [1699002745.869215][36264:36267] CHIP:DMG: }, [1699002745.869296][36264:36267] CHIP:DMG: [1699002745.869336][36264:36267] CHIP:DMG: ], [1699002745.869421][36264:36267] CHIP:DMG: [1699002745.869476][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002745.869514][36264:36267] CHIP:DMG: }, [1699002745.869780][36264:36267] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1699002745.869928][36264:36267] CHIP:CTL: Received Attestation Information from the device [1699002745.870017][36264:36267] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest' [1699002745.870075][36264:36267] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 583/583 [1699002745.870233][36264:36267] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' [1699002745.870329][36264:36267] CHIP:CTL: Performing next commissioning step 'AttestationVerification' [1699002745.870376][36264:36267] CHIP:CTL: Verifying attestation [1699002745.986779][36264:36267] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1699002745.986870][36264:36267] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification' [1699002745.986889][36264:36267] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' [1699002745.986967][36264:36267] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' [1699002745.987001][36264:36267] CHIP:CTL: Sending CSR request to 0xffffa7256480 device [1699002745.987181][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002745.987244][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002745.987542][36264:36267] CHIP:EM: <<< [E:26216i S:3193 M:120084044] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002745.988263][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002745.988318][36264:36267] CHIP:CTL: Sent CSR request, waiting for the CSR [1699002745.988461][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002745.988555][36264:36267] CHIP:DL: Long dispatch time: 123 ms, for event type 16389 [1699002746.056103][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002746.060347][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002746.060759][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002746.157744][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002746.158137][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002746.158617][36264:36267] CHIP:EM: >>> [E:26216i S:3193 M:186828892] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002746.158717][36264:36267] CHIP:EM: Found matching exchange: 26216i, Delegate: 0xffffa0e1d708 [1699002746.158832][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002746.159013][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002746.159076][36264:36267] CHIP:DMG: { [1699002746.159138][36264:36267] CHIP:DMG: suppressResponse = false, [1699002746.159181][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002746.159274][36264:36267] CHIP:DMG: [ [1699002746.159323][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002746.159413][36264:36267] CHIP:DMG: { [1699002746.159461][36264:36267] CHIP:DMG: CommandDataIB = [1699002746.159517][36264:36267] CHIP:DMG: { [1699002746.159564][36264:36267] CHIP:DMG: CommandPathIB = [1699002746.159620][36264:36267] CHIP:DMG: { [1699002746.159679][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002746.159732][36264:36267] CHIP:DMG: ClusterId = 0x3e, [1699002746.159785][36264:36267] CHIP:DMG: CommandId = 0x5, [1699002746.159827][36264:36267] CHIP:DMG: }, [1699002746.159892][36264:36267] CHIP:DMG: [1699002746.159939][36264:36267] CHIP:DMG: CommandFields = [1699002746.159990][36264:36267] CHIP:DMG: { [1699002746.160045][36264:36267] CHIP:DMG: 0x0 = [ [1699002746.160684][36264:36267] CHIP:DMG: 0x15, 0x30, 0x01, 0xca, 0x30, 0x81, 0xc7, 0x30, 0x70, 0x02, 0x01, 0x00, 0x30, 0x0e, 0x31, 0x0c, 0x30, 0x0a, 0x06, 0x03, 0x55, 0x04, 0x0a, 0x0c, 0x03, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x0f, 0xe3, 0xfa, 0xac, 0xdf, 0x75, 0xb4, 0xe5, 0x94, 0x81, 0xe1, 0xcd, 0x8b, 0x3a, 0xe4, 0xec, 0xc9, 0x01, 0x86, 0xe1, 0x51, 0x74, 0x13, 0x51, 0xad, 0x0e, 0x7f, 0x13, 0x36, 0xfb, 0x93, 0x1a, 0x2a, 0x54, 0xa4, 0x40, 0x3c, 0x28, 0xc0, 0xd2, 0x08, 0x30, 0x72, 0x8d, 0x14, 0x09, 0x7e, 0xcd, 0xe0, 0x43, 0xe1, 0xa3, 0x10, 0x0e, 0xef, 0xd7, 0xa9, 0xc4, 0x9c, 0xb1, 0x02, 0x8f, 0x72, 0x0e, 0xa0, 0x00, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x03, 0x47, 0x00, 0x30, 0x44, 0x02, 0x20, 0x0b, 0x32, 0xae, 0xd2, 0xb8, 0xde, 0x58, 0x78, 0x00, 0x9d, 0xe4, 0xe2, 0x89, 0xe8, 0xbd, 0x79, 0x77, 0x09, 0x71, 0xe5, 0xbf, 0x33, 0xd3, 0x62, 0x14, 0xb5, 0x20, 0xd9, 0x98, 0xbd, 0x1f, 0x0a, 0x02, 0x20, 0x40, 0xff, 0x0e, 0xaf, 0x77, 0x8b, 0xc1, 0x5e, 0x17, 0x90, 0xa6, 0x43, 0x67, 0xac, 0x47, 0xf5, 0x17, 0x81, 0x20, 0x6d, 0x13, 0xef, 0xba, 0xc2, 0x65, 0x37, 0x5d, 0x2d, 0x56, 0xf9, 0x60, 0xbf, 0x30, 0x02, 0x20, 0x83, 0x0c, 0xd9, 0xa6, 0x36, 0x18, 0xb8, 0x62, 0x42, 0x3f, 0xbc, 0x4d, 0x18, 0xc4, 0x31, 0x62, 0xfb, 0x7b, 0x97, 0x6a, 0x2c, 0x11, 0xba, 0xa9, 0x9f, 0x6c, 0x93, 0x5a, 0x3c, 0xda, 0xb4, 0xd4, 0x18, [1699002746.160771][36264:36267] CHIP:DMG: ] (242 bytes) [1699002746.160830][36264:36267] CHIP:DMG: 0x1 = [ [1699002746.161014][36264:36267] CHIP:DMG: 0xaf, 0x00, 0x1b, 0x81, 0x5a, 0x69, 0x89, 0xf0, 0xa4, 0xe6, 0x50, 0x97, 0x81, 0xd6, 0x1c, 0x02, 0xe9, 0xb3, 0xac, 0x46, 0x5f, 0x29, 0x65, 0x57, 0x80, 0xc1, 0x4a, 0x89, 0xf7, 0xd3, 0xe0, 0x54, 0x95, 0x97, 0xa3, 0xf1, 0xd0, 0xd8, 0x4f, 0x0d, 0x16, 0x29, 0xa8, 0xe4, 0xe2, 0xcf, 0x62, 0x38, 0xb2, 0x0c, 0x39, 0x2c, 0x9b, 0xd4, 0xff, 0x06, 0xa6, 0xdc, 0x74, 0x03, 0xe4, 0x82, 0x4d, 0x00, [1699002746.161071][36264:36267] CHIP:DMG: ] (64 bytes) [1699002746.161125][36264:36267] CHIP:DMG: }, [1699002746.161168][36264:36267] CHIP:DMG: }, [1699002746.161243][36264:36267] CHIP:DMG: [1699002746.161289][36264:36267] CHIP:DMG: }, [1699002746.161365][36264:36267] CHIP:DMG: [1699002746.161405][36264:36267] CHIP:DMG: ], [1699002746.161491][36264:36267] CHIP:DMG: [1699002746.161540][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002746.161577][36264:36267] CHIP:DMG: }, [1699002746.161839][36264:36267] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1699002746.162049][36264:36267] CHIP:CTL: Received certificate signing request from the device [1699002746.162139][36264:36267] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest' [1699002746.162191][36264:36267] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' [1699002746.162272][36264:36267] CHIP:CTL: Performing next commissioning step 'ValidateCSR' [1699002746.182829][36264:36267] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR' [1699002746.182895][36264:36267] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' [1699002746.182942][36264:36267] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' [1699002746.182972][36264:36267] CHIP:CTL: Getting certificate chain for the device from the issuer [1699002746.195880][36264:36267] CHIP:CTL: Verifying Certificate Signing Request [1699002746.203251][36264:36267] CHIP:CTL: Generating NOC [1699002746.204129][36264:36267] CHIP:CTL: Providing certificate chain to the commissioner [1699002746.204181][36264:36267] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status src/controller/ExampleOperationalCredentialsIssuer.cpp:395: Success [1699002746.204250][36264:36267] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain' [1699002746.204758][36264:36267] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' [1699002746.204806][36264:36267] CHIP:CTL: Sending root certificate to the device [1699002746.204956][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002746.205001][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002746.205273][36264:36267] CHIP:EM: <<< [E:26217i S:3193 M:120084045] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002746.205897][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002746.205953][36264:36267] CHIP:CTL: Sent root certificate to the device [1699002746.207436][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002746.299407][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002746.397996][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002746.400012][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002746.400461][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002746.401003][36264:36267] CHIP:EM: >>> [E:26217i S:3193 M:186828893] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002746.401105][36264:36267] CHIP:EM: Found matching exchange: 26217i, Delegate: 0xffffa0e1cac8 [1699002746.401217][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002746.401388][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002746.401452][36264:36267] CHIP:DMG: { [1699002746.401514][36264:36267] CHIP:DMG: suppressResponse = false, [1699002746.401559][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002746.401649][36264:36267] CHIP:DMG: [ [1699002746.401696][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002746.401775][36264:36267] CHIP:DMG: { [1699002746.401817][36264:36267] CHIP:DMG: CommandStatusIB = [1699002746.401873][36264:36267] CHIP:DMG: { [1699002746.401916][36264:36267] CHIP:DMG: CommandPathIB = [1699002746.401967][36264:36267] CHIP:DMG: { [1699002746.402026][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002746.402079][36264:36267] CHIP:DMG: ClusterId = 0x3e, [1699002746.402128][36264:36267] CHIP:DMG: CommandId = 0xb, [1699002746.402172][36264:36267] CHIP:DMG: }, [1699002746.402263][36264:36267] CHIP:DMG: [1699002746.402311][36264:36267] CHIP:DMG: StatusIB = [1699002746.402376][36264:36267] CHIP:DMG: { [1699002746.402440][36264:36267] CHIP:DMG: status = 0x00 (SUCCESS), [1699002746.402487][36264:36267] CHIP:DMG: }, [1699002746.402546][36264:36267] CHIP:DMG: [1699002746.402592][36264:36267] CHIP:DMG: }, [1699002746.402659][36264:36267] CHIP:DMG: [1699002746.402703][36264:36267] CHIP:DMG: }, [1699002746.402774][36264:36267] CHIP:DMG: [1699002746.402817][36264:36267] CHIP:DMG: ], [1699002746.402896][36264:36267] CHIP:DMG: [1699002746.402947][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002746.402985][36264:36267] CHIP:DMG: }, [1699002746.403235][36264:36267] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1699002746.403312][36264:36267] CHIP:CTL: Device confirmed that it has received the root certificate [1699002746.403389][36264:36267] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert' [1699002746.403435][36264:36267] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' [1699002746.403516][36264:36267] CHIP:CTL: Performing next commissioning step 'SendNOC' [1699002746.403805][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002746.404014][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002746.404589][36264:36267] CHIP:EM: <<< [E:26218i S:3193 M:120084046] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002746.406017][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002746.406132][36264:36267] CHIP:CTL: Sent operational certificate to the device [1699002746.406348][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002746.496087][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002746.593177][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002746.690547][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002746.692512][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002746.692903][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002746.693495][36264:36267] CHIP:EM: >>> [E:26218i S:3193 M:186828894] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002746.693598][36264:36267] CHIP:EM: Found matching exchange: 26218i, Delegate: 0xffffa0e1c908 [1699002746.693709][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002746.693883][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002746.693948][36264:36267] CHIP:DMG: { [1699002746.694011][36264:36267] CHIP:DMG: suppressResponse = false, [1699002746.694056][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002746.694148][36264:36267] CHIP:DMG: [ [1699002746.694192][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002746.694277][36264:36267] CHIP:DMG: { [1699002746.694321][36264:36267] CHIP:DMG: CommandDataIB = [1699002746.694377][36264:36267] CHIP:DMG: { [1699002746.694421][36264:36267] CHIP:DMG: CommandPathIB = [1699002746.694476][36264:36267] CHIP:DMG: { [1699002746.694540][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002746.694593][36264:36267] CHIP:DMG: ClusterId = 0x3e, [1699002746.694643][36264:36267] CHIP:DMG: CommandId = 0x8, [1699002746.694684][36264:36267] CHIP:DMG: }, [1699002746.694750][36264:36267] CHIP:DMG: [1699002746.694797][36264:36267] CHIP:DMG: CommandFields = [1699002746.694846][36264:36267] CHIP:DMG: { [1699002746.694903][36264:36267] CHIP:DMG: 0x0 = 0, [1699002746.694961][36264:36267] CHIP:DMG: 0x1 = 1, [1699002746.695012][36264:36267] CHIP:DMG: }, [1699002746.695052][36264:36267] CHIP:DMG: }, [1699002746.695122][36264:36267] CHIP:DMG: [1699002746.695163][36264:36267] CHIP:DMG: }, [1699002746.695236][36264:36267] CHIP:DMG: [1699002746.695275][36264:36267] CHIP:DMG: ], [1699002746.695362][36264:36267] CHIP:DMG: [1699002746.695412][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002746.695450][36264:36267] CHIP:DMG: }, [1699002746.695703][36264:36267] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1699002746.699941][36264:36267] CHIP:CTL: Device returned status 0 on receiving the NOC [1699002746.700027][36264:36267] CHIP:CTL: Operational credentials provisioned on device 0xffffa7256480 [1699002746.700073][36264:36267] CHIP:TOO: Secure Pairing Success [1699002746.700122][36264:36267] CHIP:TOO: CASE establishment successful [1699002746.700188][36264:36267] CHIP:CTL: Successfully finished commissioning step 'SendNOC' [1699002746.700287][36264:36267] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks [1699002746.700331][36264:36267] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'WiFiNetworkSetup' [1699002746.700411][36264:36267] CHIP:CTL: Performing next commissioning step 'WiFiNetworkSetup' [1699002746.701025][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002746.701286][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002746.701619][36264:36267] CHIP:EM: <<< [E:26219i S:3193 M:120084047] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002746.702446][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002746.702618][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002746.788441][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002746.790583][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002746.790966][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002746.791500][36264:36267] CHIP:EM: >>> [E:26219i S:3193 M:186828895] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002746.791599][36264:36267] CHIP:EM: Found matching exchange: 26219i, Delegate: 0xffffa0e1c748 [1699002746.791712][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002746.791886][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002746.791950][36264:36267] CHIP:DMG: { [1699002746.792009][36264:36267] CHIP:DMG: suppressResponse = false, [1699002746.792053][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002746.792141][36264:36267] CHIP:DMG: [ [1699002746.792184][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002746.792337][36264:36267] CHIP:DMG: { [1699002746.792384][36264:36267] CHIP:DMG: CommandDataIB = [1699002746.792442][36264:36267] CHIP:DMG: { [1699002746.792486][36264:36267] CHIP:DMG: CommandPathIB = [1699002746.792546][36264:36267] CHIP:DMG: { [1699002746.792604][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002746.792796][36264:36267] CHIP:DMG: ClusterId = 0x31, [1699002746.792858][36264:36267] CHIP:DMG: CommandId = 0x5, [1699002746.792900][36264:36267] CHIP:DMG: }, [1699002746.792972][36264:36267] CHIP:DMG: [1699002746.793019][36264:36267] CHIP:DMG: CommandFields = [1699002746.793068][36264:36267] CHIP:DMG: { [1699002746.793131][36264:36267] CHIP:DMG: 0x0 = 0, [1699002746.793259][36264:36267] CHIP:DMG: 0x2 = 0, [1699002746.793319][36264:36267] CHIP:DMG: }, [1699002746.793361][36264:36267] CHIP:DMG: }, [1699002746.793437][36264:36267] CHIP:DMG: [1699002746.793531][36264:36267] CHIP:DMG: }, [1699002746.793617][36264:36267] CHIP:DMG: [1699002746.793658][36264:36267] CHIP:DMG: ], [1699002746.793746][36264:36267] CHIP:DMG: [1699002746.793802][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002746.793841][36264:36267] CHIP:DMG: }, [1699002746.794099][36264:36267] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005 [1699002746.794355][36264:36267] CHIP:CTL: Received NetworkConfig response, networkingStatus=0 [1699002746.794450][36264:36267] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkSetup' [1699002746.794509][36264:36267] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkSetup' -> 'FailsafeBeforeWiFiEnable' [1699002746.794587][36264:36267] CHIP:CTL: Performing next commissioning step 'FailsafeBeforeWiFiEnable' [1699002746.794804][36264:36267] CHIP:CTL: Arming failsafe (66 seconds) [1699002746.795175][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002746.795283][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002746.795700][36264:36267] CHIP:EM: <<< [E:26220i S:3193 M:120084048] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002746.798339][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002746.798551][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002746.886007][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002746.888074][36264:36266] CHIP:DL: Indication received, conn = 0xffffa861a650 [1699002746.888469][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1699002746.889047][36264:36267] CHIP:EM: >>> [E:26220i S:3193 M:186828896] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002746.889173][36264:36267] CHIP:EM: Found matching exchange: 26220i, Delegate: 0xffffa0e1c588 [1699002746.889284][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002746.889461][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002746.889530][36264:36267] CHIP:DMG: { [1699002746.889592][36264:36267] CHIP:DMG: suppressResponse = false, [1699002746.889667][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002746.889758][36264:36267] CHIP:DMG: [ [1699002746.889807][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002746.889927][36264:36267] CHIP:DMG: { [1699002746.889979][36264:36267] CHIP:DMG: CommandDataIB = [1699002746.890039][36264:36267] CHIP:DMG: { [1699002746.890113][36264:36267] CHIP:DMG: CommandPathIB = [1699002746.890171][36264:36267] CHIP:DMG: { [1699002746.890256][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002746.890316][36264:36267] CHIP:DMG: ClusterId = 0x30, [1699002746.890373][36264:36267] CHIP:DMG: CommandId = 0x1, [1699002746.890438][36264:36267] CHIP:DMG: }, [1699002746.890513][36264:36267] CHIP:DMG: [1699002746.890561][36264:36267] CHIP:DMG: CommandFields = [1699002746.890638][36264:36267] CHIP:DMG: { [1699002746.890705][36264:36267] CHIP:DMG: 0x0 = 0, [1699002746.890772][36264:36267] CHIP:DMG: 0x1 = "" (0 chars), [1699002746.890857][36264:36267] CHIP:DMG: }, [1699002746.890901][36264:36267] CHIP:DMG: }, [1699002746.891007][36264:36267] CHIP:DMG: [1699002746.891052][36264:36267] CHIP:DMG: }, [1699002746.891138][36264:36267] CHIP:DMG: [1699002746.891187][36264:36267] CHIP:DMG: ], [1699002746.891301][36264:36267] CHIP:DMG: [1699002746.891358][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002746.891402][36264:36267] CHIP:DMG: }, [1699002746.891720][36264:36267] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1699002746.891913][36264:36267] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1699002746.892026][36264:36267] CHIP:CTL: Successfully finished commissioning step 'FailsafeBeforeWiFiEnable' [1699002746.892156][36264:36267] CHIP:CTL: Commissioning stage next step: 'FailsafeBeforeWiFiEnable' -> 'WiFiNetworkEnable' [1699002746.892260][36264:36267] CHIP:CTL: Setting wifi connection time min = 20 [1699002746.892364][36264:36267] CHIP:CTL: Performing next commissioning step 'WiFiNetworkEnable' [1699002746.892421][36264:36267] CHIP:CTL: SendCommand kWiFiNetworkEnable, supportsConcurrentConnection=0 [1699002746.892671][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002746.892826][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002746.893343][36264:36267] CHIP:EM: <<< [E:26221i S:3193 M:120084049] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002746.894838][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002746.894995][36264:36267] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkEnable' [1699002746.895168][36264:36267] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkEnable' -> 'FindOperational' [1699002746.895314][36264:36267] CHIP:CTL: Performing next commissioning step 'FindOperational' [1699002746.895528][36264:36267] CHIP:IN: Expiring all sessions for node <00000000000007CE, 1>!! [1699002746.895586][36264:36267] CHIP:CSM: FindOrEstablishSession: PeerId = [1:00000000000007CE] [1699002746.895861][36264:36267] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1699002746.896045][36264:36267] CHIP:DIS: OperationalSessionSetup[1:00000000000007CE]: State change 1 --> 2 [1699002746.901488][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002746.983631][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1699002747.097063][36264:36267] CHIP:DIS: Checking node lookup status after 200 ms [1699002748.076609][36264:36267] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:173: CHIP Error 0x00000032: Timeout [1699002753.165449][36264:36267] CHIP:DIS: UDP:[fe80::e65f:1ff:fec2:47af%eth0]:5540: new best score: 7 [1699002753.165670][36264:36267] CHIP:DIS: UDP:172.16.62.162%eth0:5540: score has not improved: 2 [1699002753.165731][36264:36267] CHIP:DIS: Checking node lookup status after 6269 ms [1699002753.165921][36264:36267] CHIP:DIS: OperationalSessionSetup[1:00000000000007CE]: Updating device address to UDP:[fe80::e65f:1ff:fec2:47af%eth0]:5540 while in state 2 [1699002753.165986][36264:36267] CHIP:DIS: OperationalSessionSetup[1:00000000000007CE]: State change 2 --> 3 [1699002753.166444][36264:36267] CHIP:IN: SecureSession[0xffff9d810a80]: Allocated Type:2 LSID:3194 [1699002753.166607][36264:36267] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x00000000000007CE [1699002753.174009][36264:36267] CHIP:EM: <<< [E:26222i S:0 M:82986294] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e65f:1ff:fec2:47af%eth0]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1699002753.174565][36264:36267] CHIP:SC: Sent Sigma1 msg [1699002753.174648][36264:36267] CHIP:DIS: OperationalSessionSetup[1:00000000000007CE]: State change 3 --> 4 [1699002753.531147][36264:36267] CHIP:EM: Retransmitting MessageCounter:82986294 on exchange 26222i Send Cnt 1 [1699002753.905521][36264:36267] CHIP:EM: Retransmitting MessageCounter:82986294 on exchange 26222i Send Cnt 2 [1699002754.523611][36264:36267] CHIP:EM: Retransmitting MessageCounter:82986294 on exchange 26222i Send Cnt 3 [1699002755.400845][36264:36267] CHIP:EM: Retransmitting MessageCounter:82986294 on exchange 26222i Send Cnt 4 [1699002755.426874][36264:36267] CHIP:EM: >>> [E:26222i S:0 M:211636712 (Ack:82986294)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1699002755.426936][36264:36267] CHIP:EM: Found matching exchange: 26222i, Delegate: 0xffffa0407b08 [1699002755.427023][36264:36267] CHIP:EM: Rxd Ack; Removing MessageCounter:82986294 from Retrans Table on exchange 26222i [1699002755.427166][36264:36267] CHIP:SC: Received Sigma2 msg [1699002755.427264][36264:36267] CHIP:SC: Peer assigned session session ID 27947 [1699002755.438101][36264:36267] CHIP:SC: Sending Sigma3 [1699002755.440560][36264:36267] CHIP:EM: <<< [E:26222i S:0 M:82986295 (Ack:211636712)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e65f:1ff:fec2:47af%eth0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1699002755.440903][36264:36267] CHIP:SC: Sent Sigma3 msg [1699002755.464478][36264:36267] CHIP:EM: >>> [E:26222i S:0 M:211636713 (Ack:82986295)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1699002755.464554][36264:36267] CHIP:EM: Found matching exchange: 26222i, Delegate: 0xffffa0407b08 [1699002755.464641][36264:36267] CHIP:EM: Rxd Ack; Removing MessageCounter:82986295 from Retrans Table on exchange 26222i [1699002755.464784][36264:36267] CHIP:SC: Success status report received. Session was established [1699002755.475619][36264:36267] CHIP:SC: SecureSession[0xffff9d810a80, LSID:3194]: State change 'kEstablishing' --> 'kActive' [1699002755.475731][36264:36267] CHIP:IN: SecureSession[0xffff9d810a80]: Activated - Type:2 LSID:3194 [1699002755.475781][36264:36267] CHIP:IN: New secure session activated for device <00000000000007CE, 1>, LSID:3194 PSID:27947! [1699002755.475859][36264:36267] CHIP:DIS: OperationalSessionSetup[1:00000000000007CE]: State change 4 --> 5 [1699002755.476353][36264:36267] CHIP:CTL: Successfully finished commissioning step 'FindOperational' [1699002755.476431][36264:36267] CHIP:CTL: Commissioning stage next step: 'FindOperational' -> 'SendComplete' [1699002755.476550][36264:36267] CHIP:CTL: Performing next commissioning step 'SendComplete' [1699002755.476814][36264:36267] CHIP:DMG: ICR moving to [AddingComm] [1699002755.476930][36264:36267] CHIP:DMG: ICR moving to [AddedComma] [1699002755.477612][36264:36267] CHIP:EM: <<< [E:26223i S:3194 M:21517655] (S) Msg TX to 1:00000000000007CE [40CE] [UDP:[fe80::e65f:1ff:fec2:47af%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1699002755.477901][36264:36267] CHIP:DMG: ICR moving to [CommandSen] [1699002755.478107][36264:36267] CHIP:EM: <<< [E:26222i S:0 M:82986296 (Ack:211636713)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e65f:1ff:fec2:47af%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1699002755.478229][36264:36267] CHIP:EM: Flushed pending ack for MessageCounter:211636713 on exchange 26222i [1699002755.495408][36264:36267] CHIP:EM: >>> [E:26223i S:3194 M:202569746 (Ack:21517655)] (S) Msg RX from 1:00000000000007CE [40CE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699002755.495482][36264:36267] CHIP:EM: Found matching exchange: 26223i, Delegate: 0xffffa0e21988 [1699002755.495595][36264:36267] CHIP:EM: Rxd Ack; Removing MessageCounter:21517655 from Retrans Table on exchange 26223i [1699002755.495686][36264:36267] CHIP:DMG: ICR moving to [ResponseRe] [1699002755.495839][36264:36267] CHIP:DMG: InvokeResponseMessage = [1699002755.495891][36264:36267] CHIP:DMG: { [1699002755.495945][36264:36267] CHIP:DMG: suppressResponse = false, [1699002755.495976][36264:36267] CHIP:DMG: InvokeResponseIBs = [1699002755.496052][36264:36267] CHIP:DMG: [ [1699002755.496082][36264:36267] CHIP:DMG: InvokeResponseIB = [1699002755.496159][36264:36267] CHIP:DMG: { [1699002755.496192][36264:36267] CHIP:DMG: CommandDataIB = [1699002755.496324][36264:36267] CHIP:DMG: { [1699002755.496354][36264:36267] CHIP:DMG: CommandPathIB = [1699002755.496405][36264:36267] CHIP:DMG: { [1699002755.496446][36264:36267] CHIP:DMG: EndpointId = 0x0, [1699002755.496486][36264:36267] CHIP:DMG: ClusterId = 0x30, [1699002755.496534][36264:36267] CHIP:DMG: CommandId = 0x5, [1699002755.496563][36264:36267] CHIP:DMG: }, [1699002755.496618][36264:36267] CHIP:DMG: [1699002755.496651][36264:36267] CHIP:DMG: CommandFields = [1699002755.496685][36264:36267] CHIP:DMG: { [1699002755.496744][36264:36267] CHIP:DMG: 0x0 = 0, [1699002755.496788][36264:36267] CHIP:DMG: 0x1 = "" (0 chars), [1699002755.496841][36264:36267] CHIP:DMG: }, [1699002755.496868][36264:36267] CHIP:DMG: }, [1699002755.496919][36264:36267] CHIP:DMG: [1699002755.496960][36264:36267] CHIP:DMG: }, [1699002755.497012][36264:36267] CHIP:DMG: [1699002755.497038][36264:36267] CHIP:DMG: ], [1699002755.497109][36264:36267] CHIP:DMG: [1699002755.497142][36264:36267] CHIP:DMG: InteractionModelRevision = 11 [1699002755.497180][36264:36267] CHIP:DMG: }, [1699002755.497389][36264:36267] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1699002755.497515][36264:36267] CHIP:CTL: Received CommissioningComplete response, errorCode=0 [1699002755.497573][36264:36267] CHIP:CTL: Successfully finished commissioning step 'SendComplete' [1699002755.497604][36264:36267] CHIP:CTL: Commissioning stage next step: 'SendComplete' -> 'Cleanup' [1699002755.497701][36264:36267] CHIP:CTL: Performing next commissioning step 'Cleanup' [1699002755.497750][36264:36267] CHIP:DIS: Closing all BLE connections [1699002755.497789][36264:36267] CHIP:IN: Clearing BLE pending packets. [1699002755.498721][36264:36267] CHIP:BLE: Auto-closing end point's BLE connection. [1699002755.498773][36264:36267] CHIP:DL: Closing BLE GATT connection (con 0xffffa861a650) [1699002755.499009][36264:36266] CHIP:DL: BluezDisconnect peer=E4:5F:01:C2:47:B0 [1699002757.709832][36264:36267] CHIP:IN: SecureSession[0xffffa32e2300]: MarkForEviction Type:1 LSID:3193 [1699002757.709938][36264:36267] CHIP:SC: SecureSession[0xffffa32e2300, LSID:3193]: State change 'kActive' --> 'kPendingEviction' [1699002757.710602][36264:36267] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 26221i [1699002757.710703][36264:36267] CHIP:CTL: Non-Concurrent Mode: Expected NetworkResponse Timeout, do nothing [1699002757.710755][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002757.710852][36264:36267] CHIP:IN: SecureSession[0xffffa32e2300]: Released - Type:1 LSID:3193 [1699002757.710998][36264:36267] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1699002757.711098][36264:36267] CHIP:TOO: Device commissioning completed with success [1699002757.711361][36264:36266] CHIP:DL: Bluez disconnected [1699002757.711436][36264:36266] CHIP:DL: Bluez notify CHIPoBluez connection disconnected [1699002757.711387][36264:36267] CHIP:DMG: ICR moving to [AwaitingDe] [1699002757.712132][36264:36267] CHIP:EM: <<< [E:26223i S:3194 M:21517656 (Ack:202569746)] (S) Msg TX to 1:00000000000007CE [40CE] [UDP:[fe80::e65f:1ff:fec2:47af%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1699002757.712568][36264:36267] CHIP:EM: Flushed pending ack for MessageCounter:202569746 on exchange 26223i [1699002757.712740][36264:36267] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1699002757.712800][36264:36267] CHIP:BLE: no endpoint for unsub complete [1699002757.713788][36264:36264] CHIP:CTL: Shutting down the commissioner [1699002757.714115][36264:36264] CHIP:CTL: Shutting down the controller [1699002757.714185][36264:36264] CHIP:IN: Expiring all sessions for fabric 0x1!! [1699002757.714236][36264:36264] CHIP:IN: SecureSession[0xffff9d810a80]: MarkForEviction Type:2 LSID:3194 [1699002757.714282][36264:36264] CHIP:SC: SecureSession[0xffff9d810a80, LSID:3194]: State change 'kActive' --> 'kPendingEviction' [1699002757.714326][36264:36264] CHIP:IN: SecureSession[0xffff9d810a80]: Released - Type:2 LSID:3194 [1699002757.714459][36264:36264] CHIP:FP: Forgetting fabric 0x1 [1699002757.714558][36264:36264] CHIP:TS: Pending Last Known Good Time: 2023-10-27T14:25:19 [1699002757.715613][36264:36264] CHIP:TS: Previous Last Known Good Time: 2023-10-27T14:25:19 [1699002757.715679][36264:36264] CHIP:TS: Reverted Last Known Good Time to previous value [1699002757.715919][36264:36264] CHIP:CTL: Shutting down the commissioner [1699002757.716263][36264:36264] CHIP:CTL: Shutting down the controller [1699002757.716325][36264:36264] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1699002757.718574][36264:36264] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1699002757.719042][36264:36264] CHIP:FP: Shutting down FabricTable [1699002757.719131][36264:36264] CHIP:TS: Pending Last Known Good Time: 2023-10-27T14:25:19 [1699002757.720255][36264:36264] CHIP:TS: Previous Last Known Good Time: 2023-10-27T14:25:19 [1699002757.720318][36264:36264] CHIP:TS: Reverted Last Known Good Time to previous value [1699002757.720972][36264:36264] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-VcLeQk) [1699002757.721728][36264:36264] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1699002757.721821][36264:36264] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1699002757.721851][36264:36264] CHIP:DL: Inet Layer shutdown [1699002757.721868][36264:36264] CHIP:DL: BLE shutdown [1699002757.725664][36264:36264] CHIP:DL: System Layer shutdown