wifi@wifi-Latitude-3400:~/Chip-tool/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool pairing ble-wifi 1 GRLPrivate grlprivatewifi092010 20202021 3840 [1679308641.679877][17693:17693] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1679308641.680014][17693:17693] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1679308641.680035][17693:17693] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1679308641.680049][17693:17693] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1679308641.680120][17693:17693] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-88lBj2) [1679308641.680222][17693:17693] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1679308641.680231][17693:17693] CHIP:DL: NVS set: chip-counters/reboot-count = 49 (0x31) [1679308641.680774][17693:17693] CHIP:DL: Got Ethernet interface: enp3s0 [1679308641.681243][17693:17693] CHIP:DL: Found the primary Ethernet interface:enp3s0 [1679308641.681715][17693:17693] CHIP:DL: Got WiFi interface: wlp0s20f3 [1679308641.682385][17693:17693] CHIP:DL: Found the primary WiFi interface:wlp0s20f3 [1679308641.682405][17693:17693] CHIP:IN: UDP::Init bind&listen port=0 [1679308641.682420][17693:17693] CHIP:IN: UDP::Init bound to port=35611 [1679308641.682423][17693:17693] CHIP:IN: BLEBase::Init - setting/overriding transport [1679308641.682426][17693:17693] CHIP:IN: TransportMgr initialized [1679308641.682432][17693:17693] CHIP:FP: Initializing FabricTable from persistent storage [1679308641.682463][17693:17693] CHIP:TS: Last Known Good Time: 2023-03-20T11:20:38 [1679308641.682584][17693:17693] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1AA731B702297298, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1679308641.686060][17693:17693] CHIP:ZCL: Using ZAP configuration... [1679308641.687635][17693:17693] CHIP:DL: Avahi client registered [1679308641.687871][17693:17693] CHIP:CTL: System State Initialized... [1679308641.687891][17693:17693] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1679308641.687899][17693:17693] CHIP:CTL: Setting attestation nonce to random value [1679308641.687904][17693:17693] CHIP:CTL: Setting CSR nonce to random value [1679308641.687914][17693:17693] CHIP:IN: UDP::Init bind&listen port=5550 [1679308641.687930][17693:17693] CHIP:IN: UDP::Init bound to port=5550 [1679308641.687932][17693:17693] CHIP:IN: TransportMgr initialized [1679308641.688009][17693:17695] CHIP:DL: CHIP task running [1679308641.688045][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1679308641.688092][17693:17695] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1679308641.688100][17693:17695] CHIP:CTL: Setting attestation nonce to random value [1679308641.688111][17693:17695] CHIP:CTL: Setting CSR nonce to random value [1679308641.688824][17693:17695] CHIP:CTL: Generating NOC [1679308641.689037][17693:17695] CHIP:FP: Validating NOC chain [1679308641.689352][17693:17695] CHIP:FP: NOC chain validation successful [1679308641.689386][17693:17695] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1679308641.689391][17693:17695] CHIP:TS: Last Known Good Time: 2023-03-20T11:20:38 [1679308641.689394][17693:17695] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1679308641.689396][17693:17695] CHIP:TS: Retaining current Last Known Good Time [1679308641.697585][17693:17695] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1679308641.697904][17693:17695] CHIP:TS: Committing Last Known Good Time to storage: 2023-03-20T11:20:38 [1679308641.698270][17693:17695] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 1AA731B702297298) [1679308641.698277][17693:17695] CHIP:IN: UDP::Init bind&listen port=5550 [1679308641.698289][17693:17695] CHIP:IN: UDP::Init bound to port=5550 [1679308641.698292][17693:17695] CHIP:IN: TransportMgr initialized [1679308641.700753][17693:17695] CHIP:CTL: Setting wifi credentials from parameters [1679308641.700759][17693:17695] CHIP:CTL: Setting attestation nonce to random value [1679308641.700765][17693:17695] CHIP:CTL: Setting CSR nonce to random value [1679308641.700770][17693:17695] CHIP:CTL: Commission called for node ID 0x0000000000000001 [1679308641.702166][17693:17694] CHIP:DL: TRACE: Bus acquired for name C-451d [1679308641.705125][17693:17695] CHIP:DL: PlatformBlueZInit init success [1679308641.707391][17693:17694] CHIP:BLE: BLE removing known devices. [1679308641.739152][17693:17694] CHIP:BLE: BLE initiating scan. [1679308641.882007][17693:17695] CHIP:DL: Long dispatch time: 181 ms, for event type 2 [1679308641.888219][17693:17694] CHIP:BLE: Device 21:F1:1C:8A:83:90 does not look like a CHIP device. [1679308641.888971][17693:17694] CHIP:BLE: Device EA:C0:F5:20:BD:CC does not look like a CHIP device. [1679308641.894114][17693:17694] CHIP:BLE: Device 28:C5:88:40:CE:17 does not look like a CHIP device. [1679308641.895152][17693:17694] CHIP:BLE: Device 07:69:9B:E5:76:01 does not look like a CHIP device. [1679308641.899194][17693:17694] CHIP:BLE: Device 4C:E9:0B:05:B3:2C does not look like a CHIP device. [1679308641.899595][17693:17694] CHIP:BLE: Device 11:0D:CB:33:4E:77 does not look like a CHIP device. [1679308641.902093][17693:17694] CHIP:BLE: Device 0D:2E:F7:8B:85:26 does not look like a CHIP device. [1679308641.904106][17693:17694] CHIP:BLE: Device 26:7E:A4:E0:06:7E does not look like a CHIP device. [1679308641.905145][17693:17694] CHIP:BLE: Device 27:F9:08:58:AD:14 does not look like a CHIP device. [1679308641.906790][17693:17694] CHIP:BLE: Device 24:2B:F5:48:F2:72 does not look like a CHIP device. [1679308641.912029][17693:17694] CHIP:BLE: Device 1E:9B:CC:D0:A8:AB does not look like a CHIP device. [1679308641.916128][17693:17694] CHIP:BLE: Device 4B:E9:5D:5D:38:38 does not look like a CHIP device. [1679308641.919585][17693:17694] CHIP:BLE: Device 20:24:7D:13:0D:64 does not look like a CHIP device. [1679308641.920295][17693:17694] CHIP:BLE: Device 2A:09:FF:33:2C:48 does not look like a CHIP device. [1679308641.922908][17693:17694] CHIP:BLE: Device 43:18:17:D3:51:7B does not look like a CHIP device. [1679308641.924940][17693:17694] CHIP:BLE: Device 07:18:6A:B1:49:3A does not look like a CHIP device. [1679308641.925799][17693:17694] CHIP:BLE: Device 28:E2:B4:57:8D:21 does not look like a CHIP device. [1679308641.928926][17693:17694] CHIP:BLE: Device 31:63:52:5F:AC:C2 does not look like a CHIP device. [1679308641.939295][17693:17694] CHIP:BLE: Device 72:D4:EB:FD:B7:89 does not look like a CHIP device. [1679308641.942026][17693:17694] CHIP:BLE: Device 11:22:33:45:EF:A9 does not look like a CHIP device. [1679308641.943385][17693:17694] CHIP:BLE: Device 07:05:08:41:1E:6C does not look like a CHIP device. [1679308642.016308][17693:17694] CHIP:BLE: Device 00:1B:66:2D:B6:4B does not look like a CHIP device. [1679308642.017365][17693:17694] CHIP:BLE: Device 09:DE:17:B5:85:CB does not look like a CHIP device. [1679308642.019173][17693:17694] CHIP:BLE: Device E4:41:22:E1:CD:7A does not look like a CHIP device. [1679308642.021564][17693:17694] CHIP:BLE: Device 17:68:CA:A6:52:BF does not look like a CHIP device. [1679308642.023814][17693:17694] CHIP:BLE: Device 22:57:AA:EE:5A:E3 does not look like a CHIP device. [1679308642.026093][17693:17694] CHIP:BLE: Device 35:58:07:ED:5A:1E does not look like a CHIP device. [1679308642.028047][17693:17694] CHIP:BLE: Device 3D:6F:C2:E3:50:9B does not look like a CHIP device. [1679308642.030935][17693:17694] CHIP:BLE: Device 3F:1F:8B:98:64:76 does not look like a CHIP device. [1679308642.033457][17693:17694] CHIP:BLE: Device 00:F5:83:FA:4B:01 does not look like a CHIP device. [1679308642.034858][17693:17694] CHIP:BLE: Device 1D:03:E0:22:94:EC does not look like a CHIP device. [1679308642.047872][17693:17694] CHIP:BLE: Device 33:57:30:29:E1:C2 does not look like a CHIP device. [1679308642.050093][17693:17694] CHIP:BLE: Device 35:44:0D:33:59:EE does not look like a CHIP device. [1679308642.052551][17693:17694] CHIP:BLE: Device 34:16:F9:23:D1:27 does not look like a CHIP device. [1679308642.070001][17693:17694] CHIP:BLE: Device 30:C3:57:DC:B6:E3 does not look like a CHIP device. [1679308642.074149][17693:17694] CHIP:BLE: Device 11:1C:40:69:FD:42 does not look like a CHIP device. [1679308642.077888][17693:17694] CHIP:BLE: Device 05:B1:1A:9B:5D:9C does not look like a CHIP device. [1679308642.083140][17693:17694] CHIP:BLE: Device 25:B6:1F:97:1B:6F does not look like a CHIP device. [1679308642.086949][17693:17694] CHIP:BLE: Device 66:3F:31:3C:0B:DD does not look like a CHIP device. [1679308642.100877][17693:17694] CHIP:BLE: Device 07:69:9B:E5:76:01 does not look like a CHIP device. [1679308642.104570][17693:17694] CHIP:BLE: Device 21:F1:1C:8A:83:90 does not look like a CHIP device. [1679308642.105917][17693:17694] CHIP:BLE: Device 12:73:79:DA:1C:D7 does not look like a CHIP device. [1679308642.108217][17693:17694] CHIP:BLE: Device 02:86:AD:14:98:74 does not look like a CHIP device. [1679308642.111236][17693:17694] CHIP:BLE: Device 23:23:E4:A0:09:B4 does not look like a CHIP device. [1679308642.115973][17693:17694] CHIP:BLE: Device 26:7E:A4:E0:06:7E does not look like a CHIP device. [1679308642.137442][17693:17694] CHIP:BLE: New device scanned: E4:5F:01:31:2D:1B [1679308642.137548][17693:17694] CHIP:BLE: Device discriminator match. Attempting to connect. [1679308644.811145][17693:17694] CHIP:DL: ConnectDevice complete [1679308645.981684][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.981724][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.981758][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.981779][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.981811][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.981833][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.981852][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.981866][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.981879][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.981891][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.981904][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.981916][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.981944][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0012 [1679308645.981961][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.981992][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0012 [1679308645.982011][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982038][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0012 [1679308645.982057][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982096][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.982112][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982139][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.982157][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982183][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.982202][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982250][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982267][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982301][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.982317][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982344][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.982362][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982390][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0008 [1679308645.982407][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982439][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982455][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982485][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982503][17693:17694] CHIP:DL: Char1 /org/bluez/hci0/dev_E4_5F_01_31_2D_1B/service0015 [1679308645.982539][17693:17694] CHIP:DL: New BLE connection 0x7f04b408cff0, device E4:5F:01:31:2D:1B, path /org/bluez/hci0/dev_E4_5F_01_31_2D_1B [1679308645.982672][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16385 [1679308645.982712][17693:17695] CHIP:DIS: Closing all BLE connections [1679308645.982758][17693:17695] CHIP:IN: BleConnectionComplete: endPoint 0x560cbd14ac00 [1679308645.982874][17693:17695] CHIP:IN: SecureSession[0x7f04ac020f00]: Allocated Type:1 LSID:38961 [1679308645.982897][17693:17695] CHIP:SC: Assigned local session key ID 38961 [1679308645.982964][17693:17695] CHIP:EM: <<< [E:47363i S:0 M:225178365] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1679308645.983002][17693:17695] CHIP:IN: (U) Sending msg 225178365 to IP address 'BLE' [1679308645.983029][17693:17695] CHIP:IN: Message appended to BLE send queue [1679308645.983045][17693:17695] CHIP:SC: Sent PBKDF param request [1679308646.519637][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308646.610652][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1679308646.610687][17693:17695] CHIP:BLE: subscribe complete, ep = 0x560cbd14ac00 [1679308646.611555][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308646.611652][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308646.611686][17693:17695] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1679308646.611706][17693:17695] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1679308646.611722][17693:17695] CHIP:BLE: local and remote recv window size = 6 [1679308646.611825][17693:17695] CHIP:IN: BLE EndPoint 0x560cbd14ac00 Connection Complete [1679308646.834591][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308646.837045][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308646.837181][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308646.837297][17693:17695] CHIP:EM: >>> [E:47363i S:0 M:176483136] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1679308646.837334][17693:17695] CHIP:EM: Found matching exchange: 47363i, Delegate: 0x7f04ac024600 [1679308646.837369][17693:17695] CHIP:SC: Received PBKDF param response [1679308646.837413][17693:17695] CHIP:SC: Peer assigned session ID 5642 [1679308646.841720][17693:17695] CHIP:EM: <<< [E:47363i S:0 M:225178366] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1679308646.841731][17693:17695] CHIP:IN: (U) Sending msg 225178366 to IP address 'BLE' [1679308646.841748][17693:17695] CHIP:SC: Sent spake2p msg1 [1679308646.924550][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308646.926946][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308646.927072][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308646.927165][17693:17695] CHIP:EM: >>> [E:47363i S:0 M:176483137] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1679308646.927191][17693:17695] CHIP:EM: Found matching exchange: 47363i, Delegate: 0x7f04ac024600 [1679308646.927214][17693:17695] CHIP:SC: Received spake2p msg2 [1679308646.928068][17693:17695] CHIP:EM: <<< [E:47363i S:0 M:225178367] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1679308646.928101][17693:17695] CHIP:IN: (U) Sending msg 225178367 to IP address 'BLE' [1679308646.928153][17693:17695] CHIP:SC: Sent spake2p msg3 [1679308647.014494][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308647.016249][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308647.016413][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308647.016540][17693:17695] CHIP:EM: >>> [E:47363i S:0 M:176483138] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1679308647.016581][17693:17695] CHIP:EM: Found matching exchange: 47363i, Delegate: 0x7f04ac024600 [1679308647.016685][17693:17695] CHIP:SC: SecureSession[0x7f04ac020f00]: Moving from state 'kEstablishing' --> 'kActive' [1679308647.016710][17693:17695] CHIP:IN: SecureSession[0x7f04ac020f00]: Activated - Type:1 LSID:38961 [1679308647.016733][17693:17695] CHIP:IN: New secure session activated for device , LSID:38961 PSID:5642! [1679308647.016752][17693:17695] CHIP:CTL: Remote device completed SPAKE2+ handshake [1679308647.016763][17693:17695] CHIP:TOO: Pairing Success [1679308647.016778][17693:17695] CHIP:TOO: PASE establishment successful [1679308647.016804][17693:17695] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1679308647.016829][17693:17695] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1679308647.016848][17693:17695] CHIP:CTL: Sending request for commissioning information [1679308647.016875][17693:17695] CHIP:DMG: SendReadRequest ReadClient[0x7f04ac0387b0]: Sending Read Request [1679308647.017003][17693:17695] CHIP:EM: <<< [E:47364i S:38961 M:9040380] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) [1679308647.017035][17693:17695] CHIP:IN: (S) Sending msg 9040380 on secure session with LSID: 38961 [1679308647.017098][17693:17695] CHIP:DMG: MoveToState ReadClient[0x7f04ac0387b0]: Moving to [AwaitingIn] [1679308647.104647][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308647.242691][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308647.242823][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308647.330791][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308647.330921][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308647.331052][17693:17695] CHIP:EM: >>> [E:47364i S:38961 M:182400731] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1679308647.331092][17693:17695] CHIP:EM: Found matching exchange: 47364i, Delegate: 0x7f04ac0387c0 [1679308647.331215][17693:17695] CHIP:DMG: ReportDataMessage = [1679308647.331235][17693:17695] CHIP:DMG: { [1679308647.331246][17693:17695] CHIP:DMG: AttributeReportIBs = [1679308647.331267][17693:17695] CHIP:DMG: [ [1679308647.331278][17693:17695] CHIP:DMG: AttributeReportIB = [1679308647.331297][17693:17695] CHIP:DMG: { [1679308647.331312][17693:17695] CHIP:DMG: AttributeDataIB = [1679308647.331329][17693:17695] CHIP:DMG: { [1679308647.331347][17693:17695] CHIP:DMG: DataVersion = 0xcbe8a87b, [1679308647.331368][17693:17695] CHIP:DMG: AttributePathIB = [1679308647.331385][17693:17695] CHIP:DMG: { [1679308647.331401][17693:17695] CHIP:DMG: Endpoint = 0x0, [1679308647.331417][17693:17695] CHIP:DMG: Cluster = 0x31, [1679308647.331441][17693:17695] CHIP:DMG: Attribute = 0x0000_0003, [1679308647.331456][17693:17695] CHIP:DMG: } [1679308647.331475][17693:17695] CHIP:DMG: [1679308647.331493][17693:17695] CHIP:DMG: Data = 20, [1679308647.331508][17693:17695] CHIP:DMG: }, [1679308647.331527][17693:17695] CHIP:DMG: [1679308647.331540][17693:17695] CHIP:DMG: }, [1679308647.331566][17693:17695] CHIP:DMG: [1679308647.331579][17693:17695] CHIP:DMG: AttributeReportIB = [1679308647.331599][17693:17695] CHIP:DMG: { [1679308647.331613][17693:17695] CHIP:DMG: AttributeDataIB = [1679308647.331628][17693:17695] CHIP:DMG: { [1679308647.331643][17693:17695] CHIP:DMG: DataVersion = 0x7369ef5, [1679308647.331658][17693:17695] CHIP:DMG: AttributePathIB = [1679308647.331673][17693:17695] CHIP:DMG: { [1679308647.331689][17693:17695] CHIP:DMG: Endpoint = 0x0, [1679308647.331705][17693:17695] CHIP:DMG: Cluster = 0x28, [1679308647.331722][17693:17695] CHIP:DMG: Attribute = 0x0000_0004, [1679308647.331737][17693:17695] CHIP:DMG: } [1679308647.331786][17693:17695] CHIP:DMG: [1679308647.331804][17693:17695] CHIP:DMG: Data = 32769, [1679308647.331818][17693:17695] CHIP:DMG: }, [1679308647.331837][17693:17695] CHIP:DMG: [1679308647.331851][17693:17695] CHIP:DMG: }, [1679308647.331877][17693:17695] CHIP:DMG: [1679308647.331890][17693:17695] CHIP:DMG: AttributeReportIB = [1679308647.331908][17693:17695] CHIP:DMG: { [1679308647.331919][17693:17695] CHIP:DMG: AttributeDataIB = [1679308647.331932][17693:17695] CHIP:DMG: { [1679308647.331946][17693:17695] CHIP:DMG: DataVersion = 0x7369ef5, [1679308647.331960][17693:17695] CHIP:DMG: AttributePathIB = [1679308647.331976][17693:17695] CHIP:DMG: { [1679308647.331991][17693:17695] CHIP:DMG: Endpoint = 0x0, [1679308647.332008][17693:17695] CHIP:DMG: Cluster = 0x28, [1679308647.332028][17693:17695] CHIP:DMG: Attribute = 0x0000_0002, [1679308647.332043][17693:17695] CHIP:DMG: } [1679308647.332058][17693:17695] CHIP:DMG: [1679308647.332075][17693:17695] CHIP:DMG: Data = 65521, [1679308647.332089][17693:17695] CHIP:DMG: }, [1679308647.332107][17693:17695] CHIP:DMG: [1679308647.332121][17693:17695] CHIP:DMG: }, [1679308647.332147][17693:17695] CHIP:DMG: [1679308647.332160][17693:17695] CHIP:DMG: AttributeReportIB = [1679308647.332180][17693:17695] CHIP:DMG: { [1679308647.332193][17693:17695] CHIP:DMG: AttributeDataIB = [1679308647.332207][17693:17695] CHIP:DMG: { [1679308647.332222][17693:17695] CHIP:DMG: DataVersion = 0xbad86afa, [1679308647.332237][17693:17695] CHIP:DMG: AttributePathIB = [1679308647.332253][17693:17695] CHIP:DMG: { [1679308647.332268][17693:17695] CHIP:DMG: Endpoint = 0x0, [1679308647.332284][17693:17695] CHIP:DMG: Cluster = 0x30, [1679308647.332305][17693:17695] CHIP:DMG: Attribute = 0x0000_0003, [1679308647.332320][17693:17695] CHIP:DMG: } [1679308647.332336][17693:17695] CHIP:DMG: [1679308647.332353][17693:17695] CHIP:DMG: Data = 2, [1679308647.332367][17693:17695] CHIP:DMG: }, [1679308647.332386][17693:17695] CHIP:DMG: [1679308647.332399][17693:17695] CHIP:DMG: }, [1679308647.332425][17693:17695] CHIP:DMG: [1679308647.332438][17693:17695] CHIP:DMG: AttributeReportIB = [1679308647.332458][17693:17695] CHIP:DMG: { [1679308647.332472][17693:17695] CHIP:DMG: AttributeDataIB = [1679308647.332487][17693:17695] CHIP:DMG: { [1679308647.332501][17693:17695] CHIP:DMG: DataVersion = 0xbad86afa, [1679308647.332516][17693:17695] CHIP:DMG: AttributePathIB = [1679308647.332531][17693:17695] CHIP:DMG: { [1679308647.332546][17693:17695] CHIP:DMG: Endpoint = 0x0, [1679308647.332562][17693:17695] CHIP:DMG: Cluster = 0x30, [1679308647.332579][17693:17695] CHIP:DMG: Attribute = 0x0000_0002, [1679308647.332594][17693:17695] CHIP:DMG: } [1679308647.332612][17693:17695] CHIP:DMG: [1679308647.332629][17693:17695] CHIP:DMG: Data = 0, [1679308647.332644][17693:17695] CHIP:DMG: }, [1679308647.332664][17693:17695] CHIP:DMG: [1679308647.332677][17693:17695] CHIP:DMG: }, [1679308647.332705][17693:17695] CHIP:DMG: [1679308647.332718][17693:17695] CHIP:DMG: AttributeReportIB = [1679308647.332740][17693:17695] CHIP:DMG: { [1679308647.332754][17693:17695] CHIP:DMG: AttributeDataIB = [1679308647.332769][17693:17695] CHIP:DMG: { [1679308647.332784][17693:17695] CHIP:DMG: DataVersion = 0xbad86afa, [1679308647.332799][17693:17695] CHIP:DMG: AttributePathIB = [1679308647.332814][17693:17695] CHIP:DMG: { [1679308647.332830][17693:17695] CHIP:DMG: Endpoint = 0x0, [1679308647.332846][17693:17695] CHIP:DMG: Cluster = 0x30, [1679308647.332862][17693:17695] CHIP:DMG: Attribute = 0x0000_0001, [1679308647.332877][17693:17695] CHIP:DMG: } [1679308647.332895][17693:17695] CHIP:DMG: [1679308647.332910][17693:17695] CHIP:DMG: Data = [1679308647.332925][17693:17695] CHIP:DMG: { [1679308647.332942][17693:17695] CHIP:DMG: 0x0 = 60, [1679308647.332959][17693:17695] CHIP:DMG: 0x1 = 900, [1679308647.332976][17693:17695] CHIP:DMG: }, [1679308647.332991][17693:17695] CHIP:DMG: }, [1679308647.333011][17693:17695] CHIP:DMG: [1679308647.333025][17693:17695] CHIP:DMG: }, [1679308647.333052][17693:17695] CHIP:DMG: [1679308647.333066][17693:17695] CHIP:DMG: AttributeReportIB = [1679308647.333086][17693:17695] CHIP:DMG: { [1679308647.333099][17693:17695] CHIP:DMG: AttributeDataIB = [1679308647.333113][17693:17695] CHIP:DMG: { [1679308647.333128][17693:17695] CHIP:DMG: DataVersion = 0xbad86afa, [1679308647.333142][17693:17695] CHIP:DMG: AttributePathIB = [1679308647.333157][17693:17695] CHIP:DMG: { [1679308647.333173][17693:17695] CHIP:DMG: Endpoint = 0x0, [1679308647.333190][17693:17695] CHIP:DMG: Cluster = 0x30, [1679308647.333206][17693:17695] CHIP:DMG: Attribute = 0x0000_0000, [1679308647.333222][17693:17695] CHIP:DMG: } [1679308647.333240][17693:17695] CHIP:DMG: [1679308647.333256][17693:17695] CHIP:DMG: Data = 0, [1679308647.333270][17693:17695] CHIP:DMG: }, [1679308647.333288][17693:17695] CHIP:DMG: [1679308647.333302][17693:17695] CHIP:DMG: }, [1679308647.333327][17693:17695] CHIP:DMG: [1679308647.333339][17693:17695] CHIP:DMG: AttributeReportIB = [1679308647.333359][17693:17695] CHIP:DMG: { [1679308647.333372][17693:17695] CHIP:DMG: AttributeDataIB = [1679308647.333387][17693:17695] CHIP:DMG: { [1679308647.333402][17693:17695] CHIP:DMG: DataVersion = 0xcbe8a87b, [1679308647.333417][17693:17695] CHIP:DMG: AttributePathIB = [1679308647.333432][17693:17695] CHIP:DMG: { [1679308647.333447][17693:17695] CHIP:DMG: Endpoint = 0x0, [1679308647.333464][17693:17695] CHIP:DMG: Cluster = 0x31, [1679308647.333480][17693:17695] CHIP:DMG: Attribute = 0x0000_FFFC, [1679308647.333495][17693:17695] CHIP:DMG: } [1679308647.333513][17693:17695] CHIP:DMG: [1679308647.333529][17693:17695] CHIP:DMG: Data = 1, [1679308647.333543][17693:17695] CHIP:DMG: }, [1679308647.333562][17693:17695] CHIP:DMG: [1679308647.333576][17693:17695] CHIP:DMG: }, [1679308647.333595][17693:17695] CHIP:DMG: [1679308647.333607][17693:17695] CHIP:DMG: ], [1679308647.333667][17693:17695] CHIP:DMG: [1679308647.333682][17693:17695] CHIP:DMG: SuppressResponse = true, [1679308647.333695][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308647.333708][17693:17695] CHIP:DMG: } [1679308647.334633][17693:17695] CHIP:CTL: ----- NetworkCommissioning Features: has WiFi. endpointid = 0 [1679308647.334719][17693:17695] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1679308647.334753][17693:17695] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' [1679308647.334784][17693:17695] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1679308647.334805][17693:17695] CHIP:CTL: Arming failsafe (60 seconds) [1679308647.334869][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308647.334914][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308647.334979][17693:17695] CHIP:EM: <<< [E:47365i S:38961 M:9040381] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308647.335009][17693:17695] CHIP:IN: (S) Sending msg 9040381 on secure session with LSID: 38961 [1679308647.335079][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308647.419521][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308647.421968][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308647.422082][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308647.422215][17693:17695] CHIP:EM: >>> [E:47365i S:38961 M:182400732] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308647.422244][17693:17695] CHIP:EM: Found matching exchange: 47365i, Delegate: 0x7f04b407da28 [1679308647.422267][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308647.422308][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308647.422323][17693:17695] CHIP:DMG: { [1679308647.422336][17693:17695] CHIP:DMG: suppressResponse = false, [1679308647.422350][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308647.422374][17693:17695] CHIP:DMG: [ [1679308647.422386][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308647.422407][17693:17695] CHIP:DMG: { [1679308647.422419][17693:17695] CHIP:DMG: CommandDataIB = [1679308647.422440][17693:17695] CHIP:DMG: { [1679308647.422459][17693:17695] CHIP:DMG: CommandPathIB = [1679308647.422477][17693:17695] CHIP:DMG: { [1679308647.422495][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308647.422512][17693:17695] CHIP:DMG: ClusterId = 0x30, [1679308647.422529][17693:17695] CHIP:DMG: CommandId = 0x1, [1679308647.422544][17693:17695] CHIP:DMG: }, [1679308647.422562][17693:17695] CHIP:DMG: [1679308647.422578][17693:17695] CHIP:DMG: CommandFields = [1679308647.422599][17693:17695] CHIP:DMG: { [1679308647.422617][17693:17695] CHIP:DMG: 0x0 = 0, [1679308647.422635][17693:17695] CHIP:DMG: 0x1 = "" (0 chars), [1679308647.422653][17693:17695] CHIP:DMG: }, [1679308647.422667][17693:17695] CHIP:DMG: }, [1679308647.422688][17693:17695] CHIP:DMG: [1679308647.422701][17693:17695] CHIP:DMG: }, [1679308647.422722][17693:17695] CHIP:DMG: [1679308647.422735][17693:17695] CHIP:DMG: ], [1679308647.422756][17693:17695] CHIP:DMG: [1679308647.422769][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308647.422784][17693:17695] CHIP:DMG: }, [1679308647.422840][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1679308647.422867][17693:17695] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1679308647.422895][17693:17695] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1679308647.422910][17693:17695] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1679308647.422929][17693:17695] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1679308647.422942][17693:17695] CHIP:CTL: Setting Regulatory Config [1679308647.422956][17693:17695] CHIP:CTL: No regulatory config supplied by controller, leaving as device default (0) [1679308647.422999][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308647.423041][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308647.423101][17693:17695] CHIP:EM: <<< [E:47366i S:38961 M:9040382] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308647.423128][17693:17695] CHIP:IN: (S) Sending msg 9040382 on secure session with LSID: 38961 [1679308647.423188][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308647.423260][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308647.554765][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308647.556495][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308647.556619][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308647.556793][17693:17695] CHIP:EM: >>> [E:47366i S:38961 M:182400733] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308647.556834][17693:17695] CHIP:EM: Found matching exchange: 47366i, Delegate: 0x7f04ac0214c8 [1679308647.556872][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308647.556931][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308647.556948][17693:17695] CHIP:DMG: { [1679308647.556960][17693:17695] CHIP:DMG: suppressResponse = false, [1679308647.556975][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308647.556998][17693:17695] CHIP:DMG: [ [1679308647.557011][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308647.557034][17693:17695] CHIP:DMG: { [1679308647.557047][17693:17695] CHIP:DMG: CommandDataIB = [1679308647.557062][17693:17695] CHIP:DMG: { [1679308647.557074][17693:17695] CHIP:DMG: CommandPathIB = [1679308647.557089][17693:17695] CHIP:DMG: { [1679308647.557106][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308647.557124][17693:17695] CHIP:DMG: ClusterId = 0x30, [1679308647.557140][17693:17695] CHIP:DMG: CommandId = 0x3, [1679308647.557155][17693:17695] CHIP:DMG: }, [1679308647.557174][17693:17695] CHIP:DMG: [1679308647.557192][17693:17695] CHIP:DMG: CommandFields = [1679308647.557209][17693:17695] CHIP:DMG: { [1679308647.557226][17693:17695] CHIP:DMG: 0x0 = 0, [1679308647.557247][17693:17695] CHIP:DMG: 0x1 = "" (0 chars), [1679308647.557263][17693:17695] CHIP:DMG: }, [1679308647.557277][17693:17695] CHIP:DMG: }, [1679308647.557299][17693:17695] CHIP:DMG: [1679308647.557312][17693:17695] CHIP:DMG: }, [1679308647.557331][17693:17695] CHIP:DMG: [1679308647.557345][17693:17695] CHIP:DMG: ], [1679308647.557367][17693:17695] CHIP:DMG: [1679308647.557380][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308647.557393][17693:17695] CHIP:DMG: }, [1679308647.557451][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1679308647.557509][17693:17695] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0 [1679308647.557531][17693:17695] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1679308647.557545][17693:17695] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1679308647.557564][17693:17695] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1679308647.557576][17693:17695] CHIP:CTL: Sending request for PAI certificate [1679308647.557590][17693:17695] CHIP:CTL: Sending Certificate Chain request to 0x7f04ac0245b0 device [1679308647.557639][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308647.557671][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308647.557733][17693:17695] CHIP:EM: <<< [E:47367i S:38961 M:9040383] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308647.557760][17693:17695] CHIP:IN: (S) Sending msg 9040383 on secure session with LSID: 38961 [1679308647.557820][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308647.557870][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308647.644843][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308647.648072][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308647.648245][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308647.738232][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308647.738385][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308647.826145][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308647.826300][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308647.826419][17693:17695] CHIP:EM: >>> [E:47367i S:38961 M:182400734] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308647.826447][17693:17695] CHIP:EM: Found matching exchange: 47367i, Delegate: 0x7f04b407da28 [1679308647.826473][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308647.826514][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308647.826528][17693:17695] CHIP:DMG: { [1679308647.826543][17693:17695] CHIP:DMG: suppressResponse = false, [1679308647.826558][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308647.826579][17693:17695] CHIP:DMG: [ [1679308647.826592][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308647.826613][17693:17695] CHIP:DMG: { [1679308647.826624][17693:17695] CHIP:DMG: CommandDataIB = [1679308647.826638][17693:17695] CHIP:DMG: { [1679308647.826650][17693:17695] CHIP:DMG: CommandPathIB = [1679308647.826665][17693:17695] CHIP:DMG: { [1679308647.826682][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308647.826700][17693:17695] CHIP:DMG: ClusterId = 0x3e, [1679308647.826716][17693:17695] CHIP:DMG: CommandId = 0x3, [1679308647.826732][17693:17695] CHIP:DMG: }, [1679308647.826750][17693:17695] CHIP:DMG: [1679308647.826766][17693:17695] CHIP:DMG: CommandFields = [1679308647.826782][17693:17695] CHIP:DMG: { [1679308647.826800][17693:17695] CHIP:DMG: 0x0 = [ [1679308647.826907][17693:17695] 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 [1679308647.826966][17693:17695] CHIP:DMG: ] (463 bytes) [1679308647.826983][17693:17695] CHIP:DMG: }, [1679308647.826996][17693:17695] CHIP:DMG: }, [1679308647.827016][17693:17695] CHIP:DMG: [1679308647.827029][17693:17695] CHIP:DMG: }, [1679308647.827049][17693:17695] CHIP:DMG: [1679308647.827061][17693:17695] CHIP:DMG: ], [1679308647.827083][17693:17695] CHIP:DMG: [1679308647.827096][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308647.827108][17693:17695] CHIP:DMG: }, [1679308647.827166][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1679308647.827190][17693:17695] CHIP:CTL: Received certificate chain from the device [1679308647.827211][17693:17695] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest' [1679308647.827231][17693:17695] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' [1679308647.827250][17693:17695] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' [1679308647.827263][17693:17695] CHIP:CTL: Sending request for DAC certificate [1679308647.827274][17693:17695] CHIP:CTL: Sending Certificate Chain request to 0x7f04ac0245b0 device [1679308647.827318][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308647.827336][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308647.827395][17693:17695] CHIP:EM: <<< [E:47368i S:38961 M:9040384] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308647.827421][17693:17695] CHIP:IN: (S) Sending msg 9040384 on secure session with LSID: 38961 [1679308647.827482][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308647.827531][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308647.914638][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308647.918396][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308647.918580][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308648.007946][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308648.008126][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308648.096770][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308648.096925][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308648.097058][17693:17695] CHIP:EM: >>> [E:47368i S:38961 M:182400735] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308648.097093][17693:17695] CHIP:EM: Found matching exchange: 47368i, Delegate: 0x7f04b40494f8 [1679308648.097140][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308648.097194][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308648.097215][17693:17695] CHIP:DMG: { [1679308648.097241][17693:17695] CHIP:DMG: suppressResponse = false, [1679308648.097267][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308648.097311][17693:17695] CHIP:DMG: [ [1679308648.097332][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308648.097374][17693:17695] CHIP:DMG: { [1679308648.097397][17693:17695] CHIP:DMG: CommandDataIB = [1679308648.097429][17693:17695] CHIP:DMG: { [1679308648.097456][17693:17695] CHIP:DMG: CommandPathIB = [1679308648.097488][17693:17695] CHIP:DMG: { [1679308648.097517][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308648.097549][17693:17695] CHIP:DMG: ClusterId = 0x3e, [1679308648.097576][17693:17695] CHIP:DMG: CommandId = 0x3, [1679308648.097603][17693:17695] CHIP:DMG: }, [1679308648.097637][17693:17695] CHIP:DMG: [1679308648.097665][17693:17695] CHIP:DMG: CommandFields = [1679308648.097700][17693:17695] CHIP:DMG: { [1679308648.097726][17693:17695] CHIP:DMG: 0x0 = [ [1679308648.098023][17693:17695] 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 [1679308648.098126][17693:17695] CHIP:DMG: ] (491 bytes) [1679308648.098150][17693:17695] CHIP:DMG: }, [1679308648.098180][17693:17695] CHIP:DMG: }, [1679308648.098219][17693:17695] CHIP:DMG: [1679308648.098241][17693:17695] CHIP:DMG: }, [1679308648.098281][17693:17695] CHIP:DMG: [1679308648.098301][17693:17695] CHIP:DMG: ], [1679308648.098343][17693:17695] CHIP:DMG: [1679308648.098366][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308648.098409][17693:17695] CHIP:DMG: }, [1679308648.098509][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1679308648.098544][17693:17695] CHIP:CTL: Received certificate chain from the device [1679308648.098569][17693:17695] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest' [1679308648.098595][17693:17695] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' [1679308648.098629][17693:17695] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' [1679308648.098652][17693:17695] CHIP:CTL: Sending Attestation Request to the device. [1679308648.098674][17693:17695] CHIP:CTL: Sending Attestation request to 0x7f04ac0245b0 device [1679308648.098739][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308648.098770][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308648.098859][17693:17695] CHIP:EM: <<< [E:47369i S:38961 M:9040385] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308648.098904][17693:17695] CHIP:IN: (S) Sending msg 9040385 on secure session with LSID: 38961 [1679308648.098993][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308648.099026][17693:17695] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1679308648.099093][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308648.184730][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308648.188150][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308648.188297][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308648.278403][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308648.278579][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308648.413238][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308648.413374][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308648.413514][17693:17695] CHIP:EM: >>> [E:47369i S:38961 M:182400736] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308648.413550][17693:17695] CHIP:EM: Found matching exchange: 47369i, Delegate: 0x7f04b404e1d8 [1679308648.413580][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308648.413634][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308648.413650][17693:17695] CHIP:DMG: { [1679308648.413673][17693:17695] CHIP:DMG: suppressResponse = false, [1679308648.413688][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308648.413716][17693:17695] CHIP:DMG: [ [1679308648.413732][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308648.413759][17693:17695] CHIP:DMG: { [1679308648.413774][17693:17695] CHIP:DMG: CommandDataIB = [1679308648.413790][17693:17695] CHIP:DMG: { [1679308648.413804][17693:17695] CHIP:DMG: CommandPathIB = [1679308648.413820][17693:17695] CHIP:DMG: { [1679308648.413839][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308648.413858][17693:17695] CHIP:DMG: ClusterId = 0x3e, [1679308648.413877][17693:17695] CHIP:DMG: CommandId = 0x1, [1679308648.413900][17693:17695] CHIP:DMG: }, [1679308648.413921][17693:17695] CHIP:DMG: [1679308648.413944][17693:17695] CHIP:DMG: CommandFields = [1679308648.413963][17693:17695] CHIP:DMG: { [1679308648.413983][17693:17695] CHIP:DMG: 0x0 = [ [1679308648.414108][17693:17695] CHIP:DMG: 0x15, 0x31, 0x01, 0x1c, 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 [1679308648.414174][17693:17695] CHIP:DMG: ] (584 bytes) [1679308648.414193][17693:17695] CHIP:DMG: 0x1 = [ [1679308648.414232][17693:17695] CHIP:DMG: 0x2f, 0x4b, 0x28, 0xa6, 0xa6, 0x87, 0x2c, 0x71, 0x45, 0xbd, 0x2d, 0xb9, 0xcd, 0x33, 0x9e, 0x56, 0xb4, 0xc7, 0xab, 0x64, 0x4f, 0xba, 0x4e, 0x60, 0xfa, 0x86, 0x8e, 0x96, 0xd2, 0xdf, 0xc5, 0xea, 0x7f, 0x11, 0x42, 0x8b, 0xdc, 0xc0, 0xae, 0x37, 0x89, 0xe7, 0x70, 0xc2, 0x36, 0x2c, 0x56, 0xb4, 0xf7, 0xfe, 0x80, 0xe4, 0xc7, 0x55, 0x04, 0xa7, 0xc8, 0x80, 0x46, 0xd3, 0x87, 0x10, 0x13, 0x28, [1679308648.414260][17693:17695] CHIP:DMG: ] (64 bytes) [1679308648.414278][17693:17695] CHIP:DMG: }, [1679308648.414295][17693:17695] CHIP:DMG: }, [1679308648.414318][17693:17695] CHIP:DMG: [1679308648.414333][17693:17695] CHIP:DMG: }, [1679308648.414357][17693:17695] CHIP:DMG: [1679308648.414371][17693:17695] CHIP:DMG: ], [1679308648.414396][17693:17695] CHIP:DMG: [1679308648.414411][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308648.414425][17693:17695] CHIP:DMG: }, [1679308648.414491][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1679308648.414520][17693:17695] CHIP:CTL: Received Attestation Information from the device [1679308648.414555][17693:17695] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest' [1679308648.414573][17693:17695] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 584/584 [1679308648.414615][17693:17695] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' [1679308648.414636][17693:17695] CHIP:CTL: Performing next commissioning step 'AttestationVerification' [1679308648.414650][17693:17695] CHIP:CTL: Verifying attestation [1679308648.418544][17693:17695] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1679308648.418553][17693:17695] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification' [1679308648.418558][17693:17695] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' [1679308648.418563][17693:17695] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' [1679308648.418566][17693:17695] CHIP:CTL: Sending CSR request to 0x7f04ac0245b0 device [1679308648.418584][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308648.418597][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308648.418619][17693:17695] CHIP:EM: <<< [E:47370i S:38961 M:9040386] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308648.418628][17693:17695] CHIP:IN: (S) Sending msg 9040386 on secure session with LSID: 38961 [1679308648.418650][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308648.418660][17693:17695] CHIP:CTL: Sent CSR request, waiting for the CSR [1679308648.418679][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308648.500070][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308648.503488][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308648.503608][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308648.637408][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308648.637565][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308648.637702][17693:17695] CHIP:EM: >>> [E:47370i S:38961 M:182400737] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308648.637739][17693:17695] CHIP:EM: Found matching exchange: 47370i, Delegate: 0x7f04b4058d08 [1679308648.637772][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308648.637820][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308648.637836][17693:17695] CHIP:DMG: { [1679308648.637852][17693:17695] CHIP:DMG: suppressResponse = false, [1679308648.637869][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308648.637896][17693:17695] CHIP:DMG: [ [1679308648.637911][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308648.637936][17693:17695] CHIP:DMG: { [1679308648.637953][17693:17695] CHIP:DMG: CommandDataIB = [1679308648.637971][17693:17695] CHIP:DMG: { [1679308648.637987][17693:17695] CHIP:DMG: CommandPathIB = [1679308648.638006][17693:17695] CHIP:DMG: { [1679308648.638027][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308648.638046][17693:17695] CHIP:DMG: ClusterId = 0x3e, [1679308648.638065][17693:17695] CHIP:DMG: CommandId = 0x5, [1679308648.638083][17693:17695] CHIP:DMG: }, [1679308648.638103][17693:17695] CHIP:DMG: [1679308648.638120][17693:17695] CHIP:DMG: CommandFields = [1679308648.638138][17693:17695] CHIP:DMG: { [1679308648.638157][17693:17695] CHIP:DMG: 0x0 = [ [1679308648.638258][17693:17695] 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, 0x78, 0x59, 0x3a, 0x75, 0x9c, 0xda, 0xe8, 0xdd, 0x02, 0xa1, 0xcf, 0xfd, 0xcd, 0xa8, 0x06, 0x9b, 0x38, 0xa8, 0xbf, 0x4c, 0x09, 0x89, 0x7b, 0xf9, 0x11, 0xbf, 0x34, 0x25, 0xb1, 0xa9, 0x43, 0xcf, 0xd2, 0xe4, 0x81, 0xdd, 0x85, 0x9a, 0x32, 0x64, 0x94, 0x4b, 0xec, 0xdd, 0xf0, 0x23, 0xce, 0xb1, 0x49, 0x73, 0xa7, 0xa4, 0x93, 0xdb, 0xc8, 0x52, 0x30, 0xf7, 0xcb, 0xc0, 0x0a, 0xf5, 0xf9, 0xe2, 0xa0, 0x00, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x03, 0x47, 0x00, 0x30, 0x44, 0x02, 0x20, 0x22, 0xee, 0x27, 0x85, 0x41, 0x21, 0x9f, 0xc2, 0x39, 0x74, 0x51, 0x2e, 0xe0, 0xf1, 0xd5, 0x0d, 0x7f, 0x4f, 0x72, 0x25, 0x20, 0x2e, 0xb8, 0x74, 0xe0, 0x38, 0x5e, 0xba, 0xe5, 0x4b, 0x70, 0x3b, 0x02, 0x20, 0x06, 0x87, 0xce, 0x9a, 0xb8, 0x23, 0x4b, 0x29, 0x36, 0xef, 0x40, 0x42, 0x7a, 0xc3, 0x69, 0x0c, 0x9c, 0x95, 0xab, 0xa8, 0x45, 0x00, 0x63, 0x6d, 0xd3, 0x0a, 0xb4, 0x02, 0xb0, 0xc8, 0x3d, 0x5d, 0x30, 0x02, 0x20, 0x37, 0x25, 0xf4, 0x96, 0xc2, 0x23, 0xa6, 0x16, 0x6c, 0x31, 0x63, 0xcd, 0xdc, 0xbc, 0x16, 0x37, 0xaa, 0xe3, 0x21, 0xf2, 0x1f, 0xe4, 0xf8, 0xed, 0xc7, 0x37, 0xa1, 0xcf, 0x43, 0xe3, 0xa0, 0x90, 0x18, [1679308648.638317][17693:17695] CHIP:DMG: ] (242 bytes) [1679308648.638337][17693:17695] CHIP:DMG: 0x1 = [ [1679308648.638376][17693:17695] CHIP:DMG: 0x25, 0xae, 0x5d, 0xaa, 0x5a, 0x53, 0x67, 0x35, 0x8f, 0x33, 0x52, 0x5f, 0xba, 0x09, 0x0f, 0xb0, 0x09, 0xc9, 0xfe, 0xf4, 0xe5, 0x0e, 0xf1, 0x76, 0xed, 0x3c, 0xc5, 0x49, 0xfd, 0xfb, 0xfd, 0x41, 0x94, 0xc0, 0xb3, 0x72, 0x02, 0x8e, 0xfd, 0xa8, 0x14, 0xfd, 0x96, 0xf9, 0xe5, 0xb3, 0x78, 0xfd, 0x5c, 0xc9, 0xad, 0xdc, 0x2f, 0x77, 0x00, 0x73, 0x7a, 0x92, 0x79, 0x01, 0xce, 0x7c, 0x76, 0x40, [1679308648.638401][17693:17695] CHIP:DMG: ] (64 bytes) [1679308648.638420][17693:17695] CHIP:DMG: }, [1679308648.638436][17693:17695] CHIP:DMG: }, [1679308648.638459][17693:17695] CHIP:DMG: [1679308648.638474][17693:17695] CHIP:DMG: }, [1679308648.638497][17693:17695] CHIP:DMG: [1679308648.638513][17693:17695] CHIP:DMG: ], [1679308648.638538][17693:17695] CHIP:DMG: [1679308648.638554][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308648.638568][17693:17695] CHIP:DMG: }, [1679308648.638634][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1679308648.638664][17693:17695] CHIP:CTL: Received certificate signing request from the device [1679308648.638688][17693:17695] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest' [1679308648.638706][17693:17695] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' [1679308648.638726][17693:17695] CHIP:CTL: Performing next commissioning step 'ValidateCSR' [1679308648.639842][17693:17695] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR' [1679308648.639867][17693:17695] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' [1679308648.639885][17693:17695] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' [1679308648.639903][17693:17695] CHIP:CTL: Getting certificate chain for the device from the issuer [1679308648.640135][17693:17695] CHIP:CTL: Verifying Certificate Signing Request [1679308648.640879][17693:17695] CHIP:CTL: Generating NOC [1679308648.641146][17693:17695] CHIP:CTL: Providing certificate chain to the commissioner [1679308648.641170][17693:17695] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../third_party/connectedhomeip/src/controller/ExampleOperationalCredentialsIssuer.cpp:396: Success [1679308648.641190][17693:17695] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain' [1679308648.641360][17693:17695] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' [1679308648.641377][17693:17695] CHIP:CTL: Sending root certificate to the device [1679308648.641430][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308648.641451][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308648.641519][17693:17695] CHIP:EM: <<< [E:47371i S:38961 M:9040387] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308648.641551][17693:17695] CHIP:IN: (S) Sending msg 9040387 on secure session with LSID: 38961 [1679308648.641625][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308648.641661][17693:17695] CHIP:CTL: Sent root certificate to the device [1679308648.642028][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308648.724882][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308648.815861][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308648.818121][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308648.818241][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308648.818431][17693:17695] CHIP:EM: >>> [E:47371i S:38961 M:182400738] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308648.818472][17693:17695] CHIP:EM: Found matching exchange: 47371i, Delegate: 0x7f04b404e1d8 [1679308648.818506][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308648.818558][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308648.818575][17693:17695] CHIP:DMG: { [1679308648.818596][17693:17695] CHIP:DMG: suppressResponse = false, [1679308648.818614][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308648.818643][17693:17695] CHIP:DMG: [ [1679308648.818661][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308648.818690][17693:17695] CHIP:DMG: { [1679308648.818710][17693:17695] CHIP:DMG: CommandStatusIB = [1679308648.818732][17693:17695] CHIP:DMG: { [1679308648.818751][17693:17695] CHIP:DMG: CommandPathIB = [1679308648.818775][17693:17695] CHIP:DMG: { [1679308648.818798][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308648.818822][17693:17695] CHIP:DMG: ClusterId = 0x3e, [1679308648.818845][17693:17695] CHIP:DMG: CommandId = 0xb, [1679308648.818866][17693:17695] CHIP:DMG: }, [1679308648.818894][17693:17695] CHIP:DMG: [1679308648.818915][17693:17695] CHIP:DMG: StatusIB = [1679308648.818939][17693:17695] CHIP:DMG: { [1679308648.818962][17693:17695] CHIP:DMG: status = 0x00 (SUCCESS), [1679308648.818981][17693:17695] CHIP:DMG: }, [1679308648.819004][17693:17695] CHIP:DMG: [1679308648.819023][17693:17695] CHIP:DMG: }, [1679308648.819048][17693:17695] CHIP:DMG: [1679308648.819066][17693:17695] CHIP:DMG: }, [1679308648.819091][17693:17695] CHIP:DMG: [1679308648.819114][17693:17695] CHIP:DMG: ], [1679308648.819141][17693:17695] CHIP:DMG: [1679308648.819159][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308648.819175][17693:17695] CHIP:DMG: }, [1679308648.819250][17693:17695] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1679308648.819281][17693:17695] CHIP:CTL: Device confirmed that it has received the root certificate [1679308648.819309][17693:17695] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert' [1679308648.819328][17693:17695] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' [1679308648.819351][17693:17695] CHIP:CTL: Performing next commissioning step 'SendNOC' [1679308648.819415][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308648.819451][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308648.819539][17693:17695] CHIP:EM: <<< [E:47372i S:38961 M:9040388] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308648.819582][17693:17695] CHIP:IN: (S) Sending msg 9040388 on secure session with LSID: 38961 [1679308648.819668][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308648.819700][17693:17695] CHIP:CTL: Sent operational certificate to the device [1679308648.819793][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308648.904718][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308648.994666][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308649.085043][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308649.176208][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308649.176375][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308649.176507][17693:17695] CHIP:EM: >>> [E:47372i S:38961 M:182400739] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308649.176537][17693:17695] CHIP:EM: Found matching exchange: 47372i, Delegate: 0x7f04b4058d08 [1679308649.176559][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308649.176597][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308649.176613][17693:17695] CHIP:DMG: { [1679308649.176626][17693:17695] CHIP:DMG: suppressResponse = false, [1679308649.176640][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308649.176662][17693:17695] CHIP:DMG: [ [1679308649.176675][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308649.176694][17693:17695] CHIP:DMG: { [1679308649.176707][17693:17695] CHIP:DMG: CommandDataIB = [1679308649.176720][17693:17695] CHIP:DMG: { [1679308649.176732][17693:17695] CHIP:DMG: CommandPathIB = [1679308649.176759][17693:17695] CHIP:DMG: { [1679308649.176776][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308649.176794][17693:17695] CHIP:DMG: ClusterId = 0x3e, [1679308649.176811][17693:17695] CHIP:DMG: CommandId = 0x8, [1679308649.176826][17693:17695] CHIP:DMG: }, [1679308649.176846][17693:17695] CHIP:DMG: [1679308649.176861][17693:17695] CHIP:DMG: CommandFields = [1679308649.176878][17693:17695] CHIP:DMG: { [1679308649.176896][17693:17695] CHIP:DMG: 0x0 = 0, [1679308649.176914][17693:17695] CHIP:DMG: 0x1 = 1, [1679308649.176931][17693:17695] CHIP:DMG: }, [1679308649.176945][17693:17695] CHIP:DMG: }, [1679308649.176966][17693:17695] CHIP:DMG: [1679308649.176979][17693:17695] CHIP:DMG: }, [1679308649.177001][17693:17695] CHIP:DMG: [1679308649.177014][17693:17695] CHIP:DMG: ], [1679308649.177036][17693:17695] CHIP:DMG: [1679308649.177049][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308649.177062][17693:17695] CHIP:DMG: }, [1679308649.177119][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1679308649.177146][17693:17695] CHIP:CTL: Device returned status 0 on receiving the NOC [1679308649.177160][17693:17695] CHIP:CTL: Operational credentials provisioned on device 0x7f04ac0245b0 [1679308649.177174][17693:17695] CHIP:TOO: Secure Pairing Success [1679308649.177185][17693:17695] CHIP:TOO: CASE establishment successful [1679308649.177205][17693:17695] CHIP:CTL: Successfully finished commissioning step 'SendNOC' [1679308649.177220][17693:17695] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks [1679308649.177233][17693:17695] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'WiFiNetworkSetup' [1679308649.177252][17693:17695] CHIP:CTL: Performing next commissioning step 'WiFiNetworkSetup' [1679308649.177299][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308649.177320][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308649.177377][17693:17695] CHIP:EM: <<< [E:47373i S:38961 M:9040389] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308649.177403][17693:17695] CHIP:IN: (S) Sending msg 9040389 on secure session with LSID: 38961 [1679308649.177469][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308649.177520][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308649.264713][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308649.266785][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308649.266918][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308649.267069][17693:17695] CHIP:EM: >>> [E:47373i S:38961 M:182400740] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308649.267105][17693:17695] CHIP:EM: Found matching exchange: 47373i, Delegate: 0x7f04b404e1d8 [1679308649.267151][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308649.267212][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308649.267232][17693:17695] CHIP:DMG: { [1679308649.267260][17693:17695] CHIP:DMG: suppressResponse = false, [1679308649.267284][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308649.267325][17693:17695] CHIP:DMG: [ [1679308649.267346][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308649.267390][17693:17695] CHIP:DMG: { [1679308649.267412][17693:17695] CHIP:DMG: CommandDataIB = [1679308649.267443][17693:17695] CHIP:DMG: { [1679308649.267469][17693:17695] CHIP:DMG: CommandPathIB = [1679308649.267500][17693:17695] CHIP:DMG: { [1679308649.267532][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308649.267564][17693:17695] CHIP:DMG: ClusterId = 0x31, [1679308649.267592][17693:17695] CHIP:DMG: CommandId = 0x5, [1679308649.267619][17693:17695] CHIP:DMG: }, [1679308649.267654][17693:17695] CHIP:DMG: [1679308649.267679][17693:17695] CHIP:DMG: CommandFields = [1679308649.267710][17693:17695] CHIP:DMG: { [1679308649.267768][17693:17695] CHIP:DMG: 0x0 = 0, [1679308649.267802][17693:17695] CHIP:DMG: 0x2 = 0, [1679308649.267833][17693:17695] CHIP:DMG: }, [1679308649.267858][17693:17695] CHIP:DMG: }, [1679308649.267901][17693:17695] CHIP:DMG: [1679308649.267922][17693:17695] CHIP:DMG: }, [1679308649.267963][17693:17695] CHIP:DMG: [1679308649.267984][17693:17695] CHIP:DMG: ], [1679308649.268024][17693:17695] CHIP:DMG: [1679308649.268043][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308649.268059][17693:17695] CHIP:DMG: }, [1679308649.268150][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005 [1679308649.268229][17693:17695] CHIP:CTL: Received NetworkConfig response, networkingStatus=0 [1679308649.268259][17693:17695] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkSetup' [1679308649.268285][17693:17695] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkSetup' -> 'FailsafeBeforeWiFiEnable' [1679308649.268316][17693:17695] CHIP:CTL: Performing next commissioning step 'FailsafeBeforeWiFiEnable' [1679308649.268355][17693:17695] CHIP:CTL: Arming failsafe (66 seconds) [1679308649.268418][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308649.268448][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308649.268537][17693:17695] CHIP:EM: <<< [E:47374i S:38961 M:9040390] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308649.268581][17693:17695] CHIP:IN: (S) Sending msg 9040390 on secure session with LSID: 38961 [1679308649.268670][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308649.268747][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308649.354787][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308649.356652][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308649.356899][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308649.357076][17693:17695] CHIP:EM: >>> [E:47374i S:38961 M:182400741] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308649.357119][17693:17695] CHIP:EM: Found matching exchange: 47374i, Delegate: 0x7f04b4058d08 [1679308649.357146][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308649.357192][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308649.357208][17693:17695] CHIP:DMG: { [1679308649.357221][17693:17695] CHIP:DMG: suppressResponse = false, [1679308649.357236][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308649.357261][17693:17695] CHIP:DMG: [ [1679308649.357275][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308649.357297][17693:17695] CHIP:DMG: { [1679308649.357311][17693:17695] CHIP:DMG: CommandDataIB = [1679308649.357327][17693:17695] CHIP:DMG: { [1679308649.357340][17693:17695] CHIP:DMG: CommandPathIB = [1679308649.357369][17693:17695] CHIP:DMG: { [1679308649.357388][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308649.357407][17693:17695] CHIP:DMG: ClusterId = 0x30, [1679308649.357425][17693:17695] CHIP:DMG: CommandId = 0x1, [1679308649.357442][17693:17695] CHIP:DMG: }, [1679308649.357462][17693:17695] CHIP:DMG: [1679308649.357479][17693:17695] CHIP:DMG: CommandFields = [1679308649.357496][17693:17695] CHIP:DMG: { [1679308649.357515][17693:17695] CHIP:DMG: 0x0 = 0, [1679308649.357536][17693:17695] CHIP:DMG: 0x1 = "" (0 chars), [1679308649.357555][17693:17695] CHIP:DMG: }, [1679308649.357571][17693:17695] CHIP:DMG: }, [1679308649.357594][17693:17695] CHIP:DMG: [1679308649.357609][17693:17695] CHIP:DMG: }, [1679308649.357632][17693:17695] CHIP:DMG: [1679308649.357647][17693:17695] CHIP:DMG: ], [1679308649.357670][17693:17695] CHIP:DMG: [1679308649.357685][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308649.357698][17693:17695] CHIP:DMG: }, [1679308649.357760][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1679308649.357788][17693:17695] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1679308649.357811][17693:17695] CHIP:CTL: Successfully finished commissioning step 'FailsafeBeforeWiFiEnable' [1679308649.357827][17693:17695] CHIP:CTL: Commissioning stage next step: 'FailsafeBeforeWiFiEnable' -> 'WiFiNetworkEnable' [1679308649.357843][17693:17695] CHIP:CTL: Setting wifi connection time min = 20 [1679308649.357861][17693:17695] CHIP:CTL: Performing next commissioning step 'WiFiNetworkEnable' [1679308649.357916][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308649.357939][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308649.358004][17693:17695] CHIP:EM: <<< [E:47375i S:38961 M:9040391] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308649.358033][17693:17695] CHIP:IN: (S) Sending msg 9040391 on secure session with LSID: 38961 [1679308649.358212][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308649.358275][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308649.489568][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308651.883989][17693:17695] CHIP:BLE: BLE scan error: ../../third_party/connectedhomeip/src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout [1679308651.965791][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308651.965917][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308654.664869][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1679308655.161642][17693:17694] CHIP:DL: Indication received, conn = 0x7f04b408cff0 [1679308655.161772][17693:17695] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1679308655.161904][17693:17695] CHIP:EM: >>> [E:47375i S:38961 M:182400742] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308655.161933][17693:17695] CHIP:EM: Found matching exchange: 47375i, Delegate: 0x7f04b404e1d8 [1679308655.161956][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308655.161996][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308655.162011][17693:17695] CHIP:DMG: { [1679308655.162025][17693:17695] CHIP:DMG: suppressResponse = false, [1679308655.162039][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308655.162063][17693:17695] CHIP:DMG: [ [1679308655.162076][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308655.162096][17693:17695] CHIP:DMG: { [1679308655.162110][17693:17695] CHIP:DMG: CommandDataIB = [1679308655.162126][17693:17695] CHIP:DMG: { [1679308655.162141][17693:17695] CHIP:DMG: CommandPathIB = [1679308655.162158][17693:17695] CHIP:DMG: { [1679308655.162174][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308655.162191][17693:17695] CHIP:DMG: ClusterId = 0x31, [1679308655.162207][17693:17695] CHIP:DMG: CommandId = 0x7, [1679308655.162223][17693:17695] CHIP:DMG: }, [1679308655.162244][17693:17695] CHIP:DMG: [1679308655.162259][17693:17695] CHIP:DMG: CommandFields = [1679308655.162275][17693:17695] CHIP:DMG: { [1679308655.162300][17693:17695] CHIP:DMG: 0x0 = 0, [1679308655.162317][17693:17695] CHIP:DMG: 0x2 = NULL [1679308655.162334][17693:17695] CHIP:DMG: }, [1679308655.162348][17693:17695] CHIP:DMG: }, [1679308655.162368][17693:17695] CHIP:DMG: [1679308655.162382][17693:17695] CHIP:DMG: }, [1679308655.162400][17693:17695] CHIP:DMG: [1679308655.162413][17693:17695] CHIP:DMG: ], [1679308655.162433][17693:17695] CHIP:DMG: [1679308655.162446][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308655.162457][17693:17695] CHIP:DMG: }, [1679308655.162511][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007 [1679308655.162539][17693:17695] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0 [1679308655.162564][17693:17695] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkEnable' [1679308655.162581][17693:17695] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkEnable' -> 'FindOperational' [1679308655.162599][17693:17695] CHIP:CTL: Performing next commissioning step 'FindOperational' [1679308655.162614][17693:17695] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1679308655.162629][17693:17695] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1679308655.162652][17693:17695] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1679308655.162672][17693:17695] CHIP:DIS: Resolving 1AA731B702297298:0000000000000001 ... [1679308655.163816][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308655.164236][17693:17695] CHIP:DL: Avahi resolve found [1679308655.164286][17693:17695] CHIP:DIS: Node ID resolved for 1AA731B702297298:0000000000000001 [1679308655.164303][17693:17695] CHIP:DIS: Hostname: E45F01312D1A0000 [1679308655.164322][17693:17695] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2d1a [1679308655.164336][17693:17695] CHIP:DIS: Port: 5540 [1679308655.164348][17693:17695] CHIP:DIS: Mrp Interval idle: not present [1679308655.164361][17693:17695] CHIP:DIS: Mrp Interval active: not present [1679308655.164373][17693:17695] CHIP:DIS: TCP Supported: 1 [1679308655.164512][17693:17695] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2d1a%wlp0s20f3]:5540: new best score: 3 [1679308655.164530][17693:17695] CHIP:DIS: Checking node lookup status after 2 ms [1679308655.164541][17693:17695] CHIP:DIS: Keeping DNSSD lookup active [1679308655.362679][17693:17695] CHIP:DIS: Checking node lookup status after 200 ms [1679308655.362799][17693:17695] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::e65f:1ff:fe31:2d1a%wlp0s20f3]:5540 while in state 2 [1679308655.362820][17693:17695] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1679308655.362928][17693:17695] CHIP:IN: SecureSession[0x7f04ac03bab0]: Allocated Type:2 LSID:38962 [1679308655.362965][17693:17695] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1679308655.363649][17693:17695] CHIP:EM: <<< [E:47376i S:0 M:225178368] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1679308655.363727][17693:17695] CHIP:IN: (U) Sending msg 225178368 to IP address 'UDP:[fe80::e65f:1ff:fe31:2d1a%wlp0s20f3]:5540' [1679308655.363892][17693:17695] CHIP:SC: Sent Sigma1 msg [1679308655.363913][17693:17695] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1679308655.715033][17693:17695] CHIP:EM: >>> [E:47376i S:0 M:176483139 (Ack:225178368)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1679308655.715094][17693:17695] CHIP:EM: Found matching exchange: 47376i, Delegate: 0x7f04ac0317e8 [1679308655.715126][17693:17695] CHIP:EM: Rxd Ack; Removing MessageCounter:225178368 from Retrans Table on exchange 47376i [1679308655.715162][17693:17695] CHIP:SC: Received Sigma2 msg [1679308655.715193][17693:17695] CHIP:SC: Peer assigned session session ID 5643 [1679308655.718347][17693:17695] CHIP:SC: Sending Sigma3 [1679308655.718894][17693:17695] CHIP:EM: <<< [E:47376i S:0 M:225178369 (Ack:176483139)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1679308655.719012][17693:17695] CHIP:IN: (U) Sending msg 225178369 to IP address 'UDP:[fe80::e65f:1ff:fe31:2d1a%wlp0s20f3]:5540' [1679308655.719161][17693:17695] CHIP:SC: Sent Sigma3 msg [1679308655.737251][17693:17695] CHIP:EM: >>> [E:47376i S:0 M:176483140 (Ack:225178369)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1679308655.737305][17693:17695] CHIP:EM: Found matching exchange: 47376i, Delegate: 0x7f04ac0317e8 [1679308655.737353][17693:17695] CHIP:EM: Rxd Ack; Removing MessageCounter:225178369 from Retrans Table on exchange 47376i [1679308655.737406][17693:17695] CHIP:SC: Success status report received. Session was established [1679308655.740138][17693:17695] CHIP:SC: SecureSession[0x7f04ac03bab0]: Moving from state 'kEstablishing' --> 'kActive' [1679308655.740168][17693:17695] CHIP:IN: SecureSession[0x7f04ac03bab0]: Activated - Type:2 LSID:38962 [1679308655.740181][17693:17695] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:38962 PSID:5643! [1679308655.740205][17693:17695] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1679308655.740283][17693:17695] CHIP:CTL: Successfully finished commissioning step 'FindOperational' [1679308655.740314][17693:17695] CHIP:CTL: Commissioning stage next step: 'FindOperational' -> 'SendComplete' [1679308655.740346][17693:17695] CHIP:CTL: Performing next commissioning step 'SendComplete' [1679308655.740400][17693:17695] CHIP:DMG: ICR moving to [AddingComm] [1679308655.740434][17693:17695] CHIP:DMG: ICR moving to [AddedComma] [1679308655.740541][17693:17695] CHIP:EM: <<< [E:47377i S:38962 M:255708224] (S) Msg TX to 1:0000000000000001 [7298] --- Type 0001:08 (IM:InvokeCommandRequest) [1679308655.740575][17693:17695] CHIP:IN: (S) Sending msg 255708224 on secure session with LSID: 38962 [1679308655.740735][17693:17695] CHIP:DMG: ICR moving to [CommandSen] [1679308655.740813][17693:17695] CHIP:EM: <<< [E:47376i S:0 M:225178370 (Ack:176483140)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1679308655.740927][17693:17695] CHIP:IN: (U) Sending msg 225178370 to IP address 'UDP:[fe80::e65f:1ff:fe31:2d1a%wlp0s20f3]:5540' [1679308655.741011][17693:17695] CHIP:EM: Flushed pending ack for MessageCounter:176483140 on exchange 47376i [1679308655.771647][17693:17695] CHIP:EM: >>> [E:47377i S:38962 M:214933072 (Ack:255708224)] (S) Msg RX from 1:0000000000000001 [7298] --- Type 0001:09 (IM:InvokeCommandResponse) [1679308655.771697][17693:17695] CHIP:EM: Found matching exchange: 47377i, Delegate: 0x7f04b4058d08 [1679308655.771734][17693:17695] CHIP:EM: Rxd Ack; Removing MessageCounter:255708224 from Retrans Table on exchange 47377i [1679308655.771810][17693:17695] CHIP:DMG: ICR moving to [ResponseRe] [1679308655.771870][17693:17695] CHIP:DMG: InvokeResponseMessage = [1679308655.771899][17693:17695] CHIP:DMG: { [1679308655.771923][17693:17695] CHIP:DMG: suppressResponse = false, [1679308655.771947][17693:17695] CHIP:DMG: InvokeResponseIBs = [1679308655.771985][17693:17695] CHIP:DMG: [ [1679308655.772006][17693:17695] CHIP:DMG: InvokeResponseIB = [1679308655.772048][17693:17695] CHIP:DMG: { [1679308655.772069][17693:17695] CHIP:DMG: CommandDataIB = [1679308655.772092][17693:17695] CHIP:DMG: { [1679308655.772104][17693:17695] CHIP:DMG: CommandPathIB = [1679308655.772120][17693:17695] CHIP:DMG: { [1679308655.772146][17693:17695] CHIP:DMG: EndpointId = 0x0, [1679308655.772172][17693:17695] CHIP:DMG: ClusterId = 0x30, [1679308655.772202][17693:17695] CHIP:DMG: CommandId = 0x5, [1679308655.772223][17693:17695] CHIP:DMG: }, [1679308655.772253][17693:17695] CHIP:DMG: [1679308655.772277][17693:17695] CHIP:DMG: CommandFields = [1679308655.772302][17693:17695] CHIP:DMG: { [1679308655.772330][17693:17695] CHIP:DMG: 0x0 = 0, [1679308655.772364][17693:17695] CHIP:DMG: 0x1 = "" (0 chars), [1679308655.772390][17693:17695] CHIP:DMG: }, [1679308655.772413][17693:17695] CHIP:DMG: }, [1679308655.772450][17693:17695] CHIP:DMG: [1679308655.772470][17693:17695] CHIP:DMG: }, [1679308655.772507][17693:17695] CHIP:DMG: [1679308655.772526][17693:17695] CHIP:DMG: ], [1679308655.772564][17693:17695] CHIP:DMG: [1679308655.772587][17693:17695] CHIP:DMG: InteractionModelRevision = 1 [1679308655.772607][17693:17695] CHIP:DMG: }, [1679308655.772701][17693:17695] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1679308655.772732][17693:17695] CHIP:CTL: Received CommissioningComplete response, errorCode=0 [1679308655.772760][17693:17695] CHIP:CTL: Successfully finished commissioning step 'SendComplete' [1679308655.772783][17693:17695] CHIP:CTL: Commissioning stage next step: 'SendComplete' -> 'Cleanup' [1679308655.772820][17693:17695] CHIP:CTL: Performing next commissioning step 'Cleanup' [1679308655.772845][17693:17695] CHIP:DIS: Closing all BLE connections [1679308655.772868][17693:17695] CHIP:IN: Clearing BLE pending packets. [1679308655.772925][17693:17695] CHIP:BLE: Auto-closing end point's BLE connection. [1679308655.772945][17693:17695] CHIP:DL: Closing BLE GATT connection (con 0x7f04b408cff0) [1679308655.772981][17693:17695] CHIP:IN: SecureSession[0x7f04ac020f00]: MarkForEviction Type:1 LSID:38961 [1679308655.773005][17693:17695] CHIP:SC: SecureSession[0x7f04ac020f00]: Moving from state 'kActive' --> 'kPendingEviction' [1679308655.773074][17693:17695] CHIP:IN: SecureSession[0x7f04ac020f00]: Released - Type:1 LSID:38961 [1679308655.773107][17693:17695] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1679308655.773139][17693:17695] CHIP:TOO: Device commissioning completed with success [1679308655.773208][17693:17694] CHIP:DL: BluezDisconnect peer=E4:5F:01:31:2D:1B [1679308655.773209][17693:17695] CHIP:DMG: ICR moving to [AwaitingDe] [1679308655.773374][17693:17695] CHIP:EM: <<< [E:47377i S:38962 M:255708225 (Ack:214933072)] (S) Msg TX to 1:0000000000000001 [7298] --- Type 0000:10 (SecureChannel:StandaloneAck) [1679308655.773412][17693:17695] CHIP:IN: (S) Sending msg 255708225 on secure session with LSID: 38962 [1679308655.773526][17693:17695] CHIP:EM: Flushed pending ack for MessageCounter:214933072 on exchange 47377i [1679308655.773752][17693:17693] CHIP:CTL: Shutting down the commissioner [1679308655.773782][17693:17693] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1679308655.773832][17693:17693] CHIP:CTL: Shutting down the controller [1679308655.773855][17693:17693] CHIP:IN: Expiring all sessions for fabric 0x1!! [1679308655.773876][17693:17693] CHIP:IN: SecureSession[0x7f04ac03bab0]: MarkForEviction Type:2 LSID:38962 [1679308655.773894][17693:17693] CHIP:SC: SecureSession[0x7f04ac03bab0]: Moving from state 'kActive' --> 'kPendingEviction' [1679308655.773918][17693:17693] CHIP:IN: SecureSession[0x7f04ac03bab0]: Released - Type:2 LSID:38962 [1679308655.773939][17693:17693] CHIP:FP: Forgetting fabric 0x1 [1679308655.773969][17693:17693] CHIP:TS: Pending Last Known Good Time: 2023-03-20T11:20:38 [1679308655.774129][17693:17693] CHIP:TS: Previous Last Known Good Time: 2023-03-20T11:20:38 [1679308655.774148][17693:17693] CHIP:TS: Reverted Last Known Good Time to previous value [1679308655.774184][17693:17693] CHIP:CTL: Shutting down the commissioner [1679308655.774200][17693:17693] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1679308655.774239][17693:17693] CHIP:CTL: Shutting down the controller [1679308655.774255][17693:17693] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1679308655.775841][17693:17693] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1679308655.775899][17693:17693] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1679308655.775934][17693:17693] CHIP:FP: Shutting down FabricTable [1679308655.775958][17693:17693] CHIP:TS: Pending Last Known Good Time: 2023-03-20T11:20:38 [1679308655.776079][17693:17693] CHIP:TS: Previous Last Known Good Time: 2023-03-20T11:20:38 [1679308655.776098][17693:17693] CHIP:TS: Reverted Last Known Good Time to previous value [1679308655.776318][17693:17693] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-C5wb71) [1679308655.776883][17693:17693] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1679308655.776938][17693:17693] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1679308655.776956][17693:17693] CHIP:DL: Inet Layer shutdown [1679308655.776968][17693:17693] CHIP:DL: BLE shutdown [1679308655.777787][17693:17693] CHIP:DL: System Layer shutdown wifi@wifi-Latitude-3400:~/Chip-tool/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool wifinetworkdiagnostics read beacon-rx-count 1 0 [1679308690.398924][17787:17787] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1679308690.399058][17787:17787] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1679308690.399085][17787:17787] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1679308690.399105][17787:17787] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1679308690.399180][17787:17787] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-4VBAWc) [1679308690.399303][17787:17787] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1679308690.399314][17787:17787] CHIP:DL: NVS set: chip-counters/reboot-count = 50 (0x32) [1679308690.399875][17787:17787] CHIP:DL: Got Ethernet interface: enp3s0 [1679308690.400357][17787:17787] CHIP:DL: Found the primary Ethernet interface:enp3s0 [1679308690.400838][17787:17787] CHIP:DL: Got WiFi interface: wlp0s20f3 [1679308690.403205][17787:17787] CHIP:DL: Found the primary WiFi interface:wlp0s20f3 [1679308690.403264][17787:17787] CHIP:IN: UDP::Init bind&listen port=0 [1679308690.403321][17787:17787] CHIP:IN: UDP::Init bound to port=52020 [1679308690.403336][17787:17787] CHIP:IN: BLEBase::Init - setting/overriding transport [1679308690.403348][17787:17787] CHIP:IN: TransportMgr initialized [1679308690.403369][17787:17787] CHIP:FP: Initializing FabricTable from persistent storage [1679308690.403498][17787:17787] CHIP:TS: Last Known Good Time: 2023-03-20T11:20:38 [1679308690.403954][17787:17787] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1AA731B702297298, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1679308690.405148][17787:17787] CHIP:ZCL: Using ZAP configuration... [1679308690.408913][17787:17787] CHIP:DL: Avahi client registered [1679308690.410063][17787:17787] CHIP:CTL: System State Initialized... [1679308690.410117][17787:17787] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1679308690.410142][17787:17787] CHIP:CTL: Setting attestation nonce to random value [1679308690.410170][17787:17787] CHIP:CTL: Setting CSR nonce to random value [1679308690.410206][17787:17787] CHIP:IN: UDP::Init bind&listen port=5550 [1679308690.410253][17787:17787] CHIP:IN: UDP::Init bound to port=5550 [1679308690.410264][17787:17787] CHIP:IN: TransportMgr initialized [1679308690.410411][17787:17789] CHIP:DL: CHIP task running [1679308690.410518][17787:17789] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1679308690.410644][17787:17789] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1679308690.410666][17787:17789] CHIP:CTL: Setting attestation nonce to random value [1679308690.410698][17787:17789] CHIP:CTL: Setting CSR nonce to random value [1679308690.412782][17787:17789] CHIP:CTL: Generating NOC [1679308690.413334][17787:17789] CHIP:FP: Validating NOC chain [1679308690.414195][17787:17789] CHIP:FP: NOC chain validation successful [1679308690.414289][17787:17789] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1679308690.414301][17787:17789] CHIP:TS: Last Known Good Time: 2023-03-20T11:20:38 [1679308690.414309][17787:17789] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1679308690.414315][17787:17789] CHIP:TS: Retaining current Last Known Good Time [1679308690.416525][17787:17789] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1679308690.417364][17787:17789] CHIP:TS: Committing Last Known Good Time to storage: 2023-03-20T11:20:38 [1679308690.418013][17787:17789] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 1AA731B702297298) [1679308690.418030][17787:17789] CHIP:IN: UDP::Init bind&listen port=5550 [1679308690.418057][17787:17789] CHIP:IN: UDP::Init bound to port=5550 [1679308690.418063][17787:17789] CHIP:IN: TransportMgr initialized [1679308690.422689][17787:17789] CHIP:TOO: Sending command to node 0x1 [1679308690.422757][17787:17789] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1679308690.422763][17787:17789] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1679308690.422769][17787:17789] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1679308690.422775][17787:17789] CHIP:DIS: Resolving 1AA731B702297298:0000000000000001 ... [1679308690.423241][17787:17789] CHIP:DL: Avahi resolve found [1679308690.423253][17787:17789] CHIP:DIS: Node ID resolved for 1AA731B702297298:0000000000000001 [1679308690.423277][17787:17789] CHIP:DIS: Hostname: E45F01312D1A0000 [1679308690.423285][17787:17789] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2d1a [1679308690.423290][17787:17789] CHIP:DIS: Port: 5540 [1679308690.423294][17787:17789] CHIP:DIS: Mrp Interval idle: not present [1679308690.423299][17787:17789] CHIP:DIS: Mrp Interval active: not present [1679308690.423303][17787:17789] CHIP:DIS: TCP Supported: 1 [1679308690.423352][17787:17789] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2d1a%wlp0s20f3]:5540: new best score: 3 [1679308690.423356][17787:17789] CHIP:DIS: Checking node lookup status after 1 ms [1679308690.423360][17787:17789] CHIP:DIS: Keeping DNSSD lookup active [1679308690.623103][17787:17789] CHIP:DIS: Checking node lookup status after 200 ms [1679308690.623235][17787:17789] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::e65f:1ff:fe31:2d1a%wlp0s20f3]:5540 while in state 2 [1679308690.623257][17787:17789] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1679308690.623353][17787:17789] CHIP:IN: SecureSession[0x7fdd3c0222a0]: Allocated Type:2 LSID:49672 [1679308690.623382][17787:17789] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1679308690.624069][17787:17789] CHIP:EM: <<< [E:5138i S:0 M:259402721] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1679308690.624148][17787:17789] CHIP:IN: (U) Sending msg 259402721 to IP address 'UDP:[fe80::e65f:1ff:fe31:2d1a%wlp0s20f3]:5540' [1679308690.624275][17787:17789] CHIP:SC: Sent Sigma1 msg [1679308690.624292][17787:17789] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1679308690.755497][17787:17789] CHIP:EM: >>> [E:5138i S:0 M:176483141 (Ack:259402721)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1679308690.755547][17787:17789] CHIP:EM: Found matching exchange: 5138i, Delegate: 0x7fdd3c0245b8 [1679308690.755574][17787:17789] CHIP:EM: Rxd Ack; Removing MessageCounter:259402721 from Retrans Table on exchange 5138i [1679308690.755606][17787:17789] CHIP:SC: Received Sigma2 msg [1679308690.755631][17787:17789] CHIP:SC: Peer assigned session session ID 5644 [1679308690.758141][17787:17789] CHIP:SC: Sending Sigma3 [1679308690.758505][17787:17789] CHIP:EM: <<< [E:5138i S:0 M:259402722 (Ack:176483141)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1679308690.758599][17787:17789] CHIP:IN: (U) Sending msg 259402722 to IP address 'UDP:[fe80::e65f:1ff:fe31:2d1a%wlp0s20f3]:5540' [1679308690.758713][17787:17789] CHIP:SC: Sent Sigma3 msg [1679308690.856175][17787:17789] CHIP:EM: >>> [E:5138i S:0 M:176483142 (Ack:259402722)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1679308690.856221][17787:17789] CHIP:EM: Found matching exchange: 5138i, Delegate: 0x7fdd3c0245b8 [1679308690.856250][17787:17789] CHIP:EM: Rxd Ack; Removing MessageCounter:259402722 from Retrans Table on exchange 5138i [1679308690.856283][17787:17789] CHIP:SC: Success status report received. Session was established [1679308690.858904][17787:17789] CHIP:SC: SecureSession[0x7fdd3c0222a0]: Moving from state 'kEstablishing' --> 'kActive' [1679308690.858932][17787:17789] CHIP:IN: SecureSession[0x7fdd3c0222a0]: Activated - Type:2 LSID:49672 [1679308690.858946][17787:17789] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:49672 PSID:5644! [1679308690.858974][17787:17789] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1679308690.859066][17787:17789] CHIP:TOO: cluster 0x0000_0036, attribute: 0x0000_0006, endpoint 0 [1679308690.859086][17787:17789] CHIP:TOO: Sending ReadAttribute to: [1679308690.859103][17787:17789] CHIP:DMG: SendReadRequest ReadClient[0x7fdd3c026300]: Sending Read Request [1679308690.859186][17787:17789] CHIP:EM: <<< [E:5139i S:49672 M:16441773] (S) Msg TX to 1:0000000000000001 [7298] --- Type 0001:02 (IM:ReadRequest) [1679308690.859212][17787:17789] CHIP:IN: (S) Sending msg 16441773 on secure session with LSID: 49672 [1679308690.859328][17787:17789] CHIP:DMG: MoveToState ReadClient[0x7fdd3c026300]: Moving to [AwaitingIn] [1679308690.859382][17787:17789] CHIP:EM: <<< [E:5138i S:0 M:259402723 (Ack:176483142)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1679308690.859448][17787:17789] CHIP:IN: (U) Sending msg 259402723 to IP address 'UDP:[fe80::e65f:1ff:fe31:2d1a%wlp0s20f3]:5540' [1679308690.859502][17787:17789] CHIP:EM: Flushed pending ack for MessageCounter:176483142 on exchange 5138i [1679308690.890236][17787:17789] CHIP:EM: >>> [E:5139i S:49672 M:11010441 (Ack:16441773)] (S) Msg RX from 1:0000000000000001 [7298] --- Type 0001:05 (IM:ReportData) [1679308690.890280][17787:17789] CHIP:EM: Found matching exchange: 5139i, Delegate: 0x7fdd3c026310 [1679308690.890317][17787:17789] CHIP:EM: Rxd Ack; Removing MessageCounter:16441773 from Retrans Table on exchange 5139i [1679308690.890366][17787:17789] CHIP:DMG: ReportDataMessage = [1679308690.890379][17787:17789] CHIP:DMG: { [1679308690.890389][17787:17789] CHIP:DMG: AttributeReportIBs = [1679308690.890407][17787:17789] CHIP:DMG: [ [1679308690.890419][17787:17789] CHIP:DMG: AttributeReportIB = [1679308690.890437][17787:17789] CHIP:DMG: { [1679308690.890449][17787:17789] CHIP:DMG: AttributeDataIB = [1679308690.890464][17787:17789] CHIP:DMG: { [1679308690.890478][17787:17789] CHIP:DMG: DataVersion = 0xd91c452b, [1679308690.890490][17787:17789] CHIP:DMG: AttributePathIB = [1679308690.890503][17787:17789] CHIP:DMG: { [1679308690.890517][17787:17789] CHIP:DMG: Endpoint = 0x0, [1679308690.890531][17787:17789] CHIP:DMG: Cluster = 0x36, [1679308690.890545][17787:17789] CHIP:DMG: Attribute = 0x0000_0006, [1679308690.890558][17787:17789] CHIP:DMG: } [1679308690.890573][17787:17789] CHIP:DMG: [1679308690.890587][17787:17789] CHIP:DMG: Data = NULL [1679308690.890599][17787:17789] CHIP:DMG: }, [1679308690.890615][17787:17789] CHIP:DMG: [1679308690.890626][17787:17789] CHIP:DMG: }, [1679308690.890642][17787:17789] CHIP:DMG: [1679308690.890652][17787:17789] CHIP:DMG: ], [1679308690.890669][17787:17789] CHIP:DMG: [1679308690.890680][17787:17789] CHIP:DMG: SuppressResponse = true, [1679308690.890691][17787:17789] CHIP:DMG: InteractionModelRevision = 1 [1679308690.890702][17787:17789] CHIP:DMG: } [1679308690.890811][17787:17789] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0036 Attribute 0x0000_0006 DataVersion: 3642508587 [1679308690.890853][17787:17789] CHIP:TOO: BeaconRxCount: null [1679308690.890940][17787:17789] CHIP:EM: <<< [E:5139i S:49672 M:16441774 (Ack:11010441)] (S) Msg TX to 1:0000000000000001 [7298] --- Type 0000:10 (SecureChannel:StandaloneAck) [1679308690.890963][17787:17789] CHIP:IN: (S) Sending msg 16441774 on secure session with LSID: 49672 [1679308690.891030][17787:17789] CHIP:EM: Flushed pending ack for MessageCounter:11010441 on exchange 5139i [1679308690.891152][17787:17787] CHIP:CTL: Shutting down the commissioner [1679308690.891178][17787:17787] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1679308690.891222][17787:17787] CHIP:CTL: Shutting down the controller [1679308690.891238][17787:17787] CHIP:IN: Expiring all sessions for fabric 0x1!! [1679308690.891250][17787:17787] CHIP:IN: SecureSession[0x7fdd3c0222a0]: MarkForEviction Type:2 LSID:49672 [1679308690.891263][17787:17787] CHIP:SC: SecureSession[0x7fdd3c0222a0]: Moving from state 'kActive' --> 'kPendingEviction' [1679308690.891273][17787:17787] CHIP:IN: SecureSession[0x7fdd3c0222a0]: Released - Type:2 LSID:49672 [1679308690.891288][17787:17787] CHIP:FP: Forgetting fabric 0x1 [1679308690.891310][17787:17787] CHIP:TS: Pending Last Known Good Time: 2023-03-20T11:20:38 [1679308690.891476][17787:17787] CHIP:TS: Previous Last Known Good Time: 2023-03-20T11:20:38 [1679308690.891492][17787:17787] CHIP:TS: Reverted Last Known Good Time to previous value [1679308690.891520][17787:17787] CHIP:CTL: Shutting down the commissioner [1679308690.891531][17787:17787] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1679308690.891561][17787:17787] CHIP:CTL: Shutting down the controller [1679308690.891573][17787:17787] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1679308690.892387][17787:17787] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1679308690.892425][17787:17787] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1679308690.892447][17787:17787] CHIP:FP: Shutting down FabricTable [1679308690.892461][17787:17787] CHIP:TS: Pending Last Known Good Time: 2023-03-20T11:20:38 [1679308690.892535][17787:17787] CHIP:TS: Previous Last Known Good Time: 2023-03-20T11:20:38 [1679308690.892546][17787:17787] CHIP:TS: Reverted Last Known Good Time to previous value [1679308690.892705][17787:17787] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-J1gGvb) [1679308690.893077][17787:17787] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1679308690.893144][17787:17787] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1679308690.893166][17787:17787] CHIP:DL: Inet Layer shutdown [1679308690.893188][17787:17787] CHIP:DL: BLE shutdown