[1708108369.886989][12951:12951] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1708108369.888226][12951:12951] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1708108369.888264][12951:12951] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1708108369.894416][12951:12951] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1708108369.894730][12951:12951] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1708108369.894869][12951:12951] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1708108369.895307][12951:12951] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-P9tS83)
[1708108369.896040][12951:12951] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1708108369.896104][12951:12951] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1708108369.896863][12951:12951] CHIP:DL: Got Ethernet interface: eth0
[1708108369.897350][12951:12951] CHIP:DL: Found the primary Ethernet interface:eth0
[1708108369.897861][12951:12951] CHIP:DL: Got WiFi interface: wlan0
[1708108369.897958][12951:12951] CHIP:DL: Failed to reset WiFi statistic counts
[1708108369.898014][12951:12951] CHIP:IN: UDP::Init bind&listen port=0
[1708108369.898132][12951:12951] CHIP:IN: UDP::Init bound to port=33308
[1708108369.898156][12951:12951] CHIP:IN: BLEBase::Init - setting/overriding transport
[1708108369.898177][12951:12951] CHIP:IN: TransportMgr initialized
[1708108369.898231][12951:12951] CHIP:FP: Initializing FabricTable from persistent storage
[1708108369.898395][12951:12951] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1708108369.900168][12951:12951] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1B198FF438B9ACF7, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1708108369.902367][12951:12951] CHIP:ZCL: Using ZAP configuration...
[1708108369.906499][12951:12951] CHIP:DL: Avahi client registered
[1708108369.906630][12951:12951] CHIP:CTL: System State Initialized...
[1708108369.906810][12951:12951] CHIP:CTL: Setting attestation nonce to random value
[1708108369.906851][12951:12951] CHIP:CTL: Setting CSR nonce to random value
[1708108369.906953][12951:12951] CHIP:IN: UDP::Init bind&listen port=5550
[1708108369.907107][12951:12951] CHIP:IN: UDP::Init bound to port=5550
[1708108369.907132][12951:12951] CHIP:IN: TransportMgr initialized
[1708108369.907448][12951:12953] CHIP:DL: CHIP task running
[1708108369.907686][12951:12953] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1708108369.908050][12951:12953] CHIP:CTL: Setting attestation nonce to random value
[1708108369.908228][12951:12953] CHIP:CTL: Setting CSR nonce to random value
[1708108369.909231][12951:12953] CHIP:CTL: Generating NOC
[1708108369.910374][12951:12953] CHIP:FP: Validating NOC chain
[1708108369.912703][12951:12953] CHIP:FP: NOC chain validation successful
[1708108369.912907][12951:12953] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1708108369.912948][12951:12953] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1708108369.912977][12951:12953] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1708108369.913002][12951:12953] CHIP:TS: Retaining current Last Known Good Time
[1708108369.915355][12951:12953] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1708108369.917503][12951:12953] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1708108369.919435][12951:12953] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 1B198FF438B9ACF7)
[1708108369.919487][12951:12953] CHIP:IN: UDP::Init bind&listen port=5550
[1708108369.919607][12951:12953] CHIP:IN: UDP::Init bound to port=5550
[1708108369.919633][12951:12953] CHIP:IN: TransportMgr initialized
[1708108369.939374][12951:12953] CHIP:CTL: Setting wifi credentials from parameters
[1708108369.939419][12951:12953] CHIP:CTL: Setting attestation nonce to random value
[1708108369.939494][12951:12953] CHIP:CTL: Setting CSR nonce to random value
[1708108369.939532][12951:12953] CHIP:CTL: Checking ICD registration parameters
[1708108369.939574][12951:12953] CHIP:CTL: Commission called for node ID 0x0000000000000050
[1708108369.954035][12951:12953] CHIP:DL: BlueZ integration init success
[1708108369.960875][12951:12952] CHIP:BLE: BLE removing known devices.
[1708108369.962887][12951:12952] CHIP:BLE: BLE initiating scan.
[1708108369.965933][12951:12953] CHIP:BLE: ChipDeviceScanner has started scanning!
[1708108369.972946][12951:12952] CHIP:BLE: Device 7A:70:69:32:C1:D5 does not look like a CHIP device.
[1708108369.977394][12951:12952] CHIP:BLE: Device 45:BE:F4:A5:7D:C0 does not look like a CHIP device.
[1708108369.980721][12951:12952] CHIP:BLE: Device FD:C4:DE:53:AE:CD does not look like a CHIP device.
[1708108369.982896][12951:12952] CHIP:BLE: Device 09:7E:AE:6E:D7:46 does not look like a CHIP device.
[1708108369.984469][12951:12952] CHIP:BLE: Device C0:D3:29:52:BF:65 does not look like a CHIP device.
[1708108369.985966][12951:12952] CHIP:BLE: Device 63:59:6B:7B:E1:0E does not look like a CHIP device.
[1708108370.001132][12951:12952] CHIP:BLE: Device 00:23:06:FC:ED:BC does not look like a CHIP device.
[1708108370.010878][12951:12952] CHIP:BLE: Device 70:BF:92:00:85:66 does not look like a CHIP device.
[1708108370.024365][12951:12952] CHIP:BLE: Device 4D:37:11:17:66:8D does not look like a CHIP device.
[1708108370.046655][12951:12952] CHIP:BLE: Device 6E:03:1D:E7:D7:49 does not look like a CHIP device.
[1708108370.053432][12951:12952] CHIP:BLE: Device F3:33:60:81:3B:E1 does not look like a CHIP device.
[1708108370.088099][12951:12952] CHIP:BLE: Device 16:DE:BD:41:D0:9F does not look like a CHIP device.
[1708108370.132931][12951:12952] CHIP:BLE: Device 7C:E6:A8:59:A7:2B does not look like a CHIP device.
[1708108370.169070][12951:12952] CHIP:BLE: New device scanned: DC:A6:32:98:8C:EC
[1708108370.169155][12951:12952] CHIP:BLE: Device discriminator match. Attempting to connect.
[1708108370.174434][12951:12952] CHIP:BLE: ChipDeviceScanner has stopped scanning!
[1708108372.877627][12951:12952] CHIP:DL: ConnectDevice complete
[1708108372.877712][12951:12952] CHIP:BLE: New device connected: DC:A6:32:98:8C:EC
[1708108374.295074][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0008 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295136][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0008 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295173][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0012 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295209][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0012 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295249][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0008 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295280][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0008 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295322][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0008 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295353][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0008 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295386][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295419][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295456][12951:12952] CHIP:DL: Char /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039 on service /org/bluez/hci0/dev_DC_A6_32_98_8C_EC/service0039
[1708108374.295522][12951:12952] CHIP:DL: New BLE connection: conn 0xffff7c032600, device DC:A6:32:98:8C:EC, path /org/bluez/hci0/dev_DC_A6_32_98_8C_EC
[1708108374.295674][12951:12953] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1708108374.295721][12951:12953] CHIP:DIS: Closing all BLE connections
[1708108374.295794][12951:12953] CHIP:IN: BleConnectionComplete: endPoint 0xaaaadd326358
[1708108374.296557][12951:12953] CHIP:IN: SecureSession[0xffff840116f0]: Allocated Type:1 LSID:936
[1708108374.296616][12951:12953] CHIP:SC: Assigned local session key ID 936
[1708108374.296743][12951:12953] CHIP:EM: <<< [E:11845i S:0 M:179379553] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1708108374.296829][12951:12953] CHIP:IN: Message appended to BLE send queue
[1708108374.296895][12951:12953] CHIP:SC: Sent PBKDF param request
[1708108374.729119][12951:12953] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1708108374.827783][12951:12953] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1708108374.827868][12951:12953] CHIP:BLE: subscribe complete, ep = 0xaaaadd326358
[1708108389.310564][12951:12953] CHIP:BLE: connect handshake timed out, closing ep 0xaaaadd326358
[1708108389.310678][12951:12953] CHIP:IN: Failed to establish BLE connection: src/ble/BLEEndPoint.cpp:1522: Ble Error 0x00000415: Connect handshake timed out
[1708108389.310734][12951:12953] CHIP:IN: Clearing BLE pending packets.
[1708108389.314769][12951:12953] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1708108389.314853][12951:12953] CHIP:BLE: Auto-closing end point's BLE connection.
[1708108389.314907][12951:12953] CHIP:DL: Closing BLE GATT connection (con 0xffff7c032600)
[1708108389.315094][12951:12952] CHIP:DL: BluezDisconnect peer=DC:A6:32:98:8C:EC
[1708108391.793355][12951:12953] CHIP:DL: Long dispatch time: 2479 ms, for event type 16388
[1708108391.793538][12951:12953] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
[1708108391.793627][12951:12953] CHIP:IN: SecureSession[0xffff840116f0]: Released - Type:1 LSID:936
[1708108391.793691][12951:12953] CHIP:TOO: Secure Pairing Failed
[1708108391.793788][12951:12953] CHIP:DIS: Closing all BLE connections
[1708108391.793872][12951:12953] CHIP:TOO: Pairing Failure: src/protocols/secure_channel/PASESession.cpp:258: CHIP Error 0x00000032: Timeout
[1708108391.793874][12951:12952] CHIP:DL: Bluez disconnected
[1708108391.794211][12951:12952] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1708108391.794439][12951:12951] CHIP:CTL: Shutting down the commissioner
[1708108391.794615][12951:12951] CHIP:CTL: Shutting down the controller
[1708108391.794719][12951:12951] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1708108391.794777][12951:12951] CHIP:FP: Forgetting fabric 0x1
[1708108391.794850][12951:12951] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1708108391.795169][12951:12951] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1708108391.795233][12951:12951] CHIP:TS: Reverted Last Known Good Time to previous value
[1708108391.795319][12951:12951] CHIP:CTL: Shutting down the commissioner
[1708108391.795485][12951:12951] CHIP:CTL: Shutting down the controller
[1708108391.795539][12951:12951] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1708108391.795832][12951:12951] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1708108391.796069][12951:12951] CHIP:FP: Shutting down FabricTable
[1708108391.796159][12951:12951] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1708108391.796396][12951:12951] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1708108391.796450][12951:12951] CHIP:TS: Reverted Last Known Good Time to previous value
[1708108391.796907][12951:12951] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-9BUlTI)
[1708108391.798148][12951:12951] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1708108391.798289][12951:12951] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1708108391.798351][12951:12951] CHIP:DL: Inet Layer shutdown
[1708108391.798401][12951:12951] CHIP:DL: BLE shutdown
[1708108391.803252][12951:12951] CHIP:DL: System Layer shutdown
[1708108391.804592][12951:12951] CHIP:TOO: Run command failure: src/protocols/secure_channel/PASESession.cpp:258: CHIP Error 0x00000032: Timeout