./chip-tool-debug pairing ble-thread 1 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fd9b8b7910124b0b051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0f7f8 20202021 3840
[1657975031.238085][45387:45387] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1657975031.238204][45387:45387] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1657975031.238233][45387:45387] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1657975031.238249][45387:45387] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1657975031.238323][45387:45387] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-itCJp9)
[1657975031.238440][45387:45387] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657975031.238450][45387:45387] CHIP:DL: NVS set: chip-counters/reboot-count = 7 (0x7)
[1657975031.238624][45387:45387] CHIP:DL: Got Ethernet interface: enp0s31f6
[1657975031.238734][45387:45387] CHIP:DL: Found the primary Ethernet interface:enp0s31f6
[1657975031.238845][45387:45387] CHIP:DL: Got WiFi interface: wlp2s0
[1657975031.238865][45387:45387] CHIP:DL: Failed to reset WiFi statistic counts
[1657975031.238880][45387:45387] CHIP:IN: UDP::Init bind&listen port=0
[1657975031.238898][45387:45387] CHIP:IN: UDP::Init bound to port=57268
[1657975031.238903][45387:45387] CHIP:IN: UDP::Init bind&listen port=0
[1657975031.238916][45387:45387] CHIP:IN: UDP::Init bound to port=47812
[1657975031.238920][45387:45387] CHIP:IN: BLEBase::Init - setting/overriding transport
[1657975031.238923][45387:45387] CHIP:IN: TransportMgr initialized
[1657975031.238939][45387:45387] CHIP:DIS: Init fabric pairing table with server storage
[1657975031.238972][45387:45387] CHIP:IN: Loading from storage for fabric index 0x1
[1657975031.239863][45387:45387] CHIP:IN: Loading from storage for fabric index 0x2
[1657975031.240045][45387:45387] CHIP:IN: Loading from storage for fabric index 0x3
[1657975031.240233][45387:45387] CHIP:DIS: Add fabric pairing table delegate
[1657975031.240677][45387:45387] CHIP:ZCL: Using ZAP configuration...
[1657975031.241826][45387:45387] CHIP:DL: Avahi client registered
[1657975031.242156][45387:45387] CHIP:CTL: System State Initialized...
[1657975031.242178][45387:45387] CHIP:CTL: Setting attestation nonce to random value
[1657975031.242185][45387:45387] CHIP:CTL: Setting CSR nonce to random value
[1657975031.242214][45387:45387] CHIP:CTL: Setting attestation nonce to random value
[1657975031.242221][45387:45387] CHIP:CTL: Setting CSR nonce to random value
[1657975031.242451][45387:45387] CHIP:CTL: Generating NOC
[1657975031.242651][45387:45387] CHIP:DIS: Verifying the received credentials
[1657975031.243092][45387:45387] CHIP:DIS: Added new fabric at index: 0x1, Initialized: 1
[1657975031.243098][45387:45387] CHIP:DIS: Assigned compressed fabric ID: 0x4E82D91B745DC966, node ID: 0x000000000001B669
[1657975031.244088][45387:45387] CHIP:DIS: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
[1657975031.244095][45387:45387] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x4E82D91B745DC966
[1657975031.244115][45387:45387] CHIP:CTL: Setting attestation nonce to random value
[1657975031.244122][45387:45387] CHIP:CTL: Setting CSR nonce to random value
[1657975031.244323][45387:45387] CHIP:CTL: Generating NOC
[1657975031.244521][45387:45387] CHIP:DIS: Verifying the received credentials
[1657975031.244953][45387:45387] CHIP:DIS: Added new fabric at index: 0x2, Initialized: 1
[1657975031.244960][45387:45387] CHIP:DIS: Assigned compressed fabric ID: 0xB6DAADDB211BFD9C, node ID: 0x000000000001B669
[1657975031.245920][45387:45387] CHIP:DIS: Fabric (2) persisted to storage. Calling OnFabricPersistedToStorage
[1657975031.245926][45387:45387] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xB6DAADDB211BFD9C
[1657975031.245944][45387:45387] CHIP:CTL: Setting attestation nonce to random value
[1657975031.245951][45387:45387] CHIP:CTL: Setting CSR nonce to random value
[1657975031.246150][45387:45387] CHIP:CTL: Generating NOC
[1657975031.246356][45387:45387] CHIP:DIS: Verifying the received credentials
[1657975031.246792][45387:45387] CHIP:DIS: Added new fabric at index: 0x3, Initialized: 1
[1657975031.246799][45387:45387] CHIP:DIS: Assigned compressed fabric ID: 0xEE69A1828A93411A, node ID: 0x000000000001B669
[1657975031.247739][45387:45387] CHIP:DIS: Fabric (3) persisted to storage. Calling OnFabricPersistedToStorage
[1657975031.247745][45387:45387] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xEE69A1828A93411A
[1657975031.253059][45387:45392] CHIP:DL: CHIP task running
[1657975031.253108][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 32787
[1657975031.253146][45387:45392] CHIP:SC: Assigned local session key ID 39540
[1657975031.253159][45387:45392] CHIP:SC: Including MRP parameters in PBKDF param request
[1657975031.253170][45387:45392] CHIP:IN: Prepared unauthenticated message 0x7f26e7ffe380 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 54953i with MessageCounter:2493225122.
[1657975031.253178][45387:45392] CHIP:IN: Sending unauthenticated msg 0x7f26e7ffe380 with MessageCounter:2493225122 to 0x0000000000000000 at monotonic time: 0000000000B2B7F0 msec
[1657975031.253184][45387:45392] CHIP:IN: Message appended to BLE send queue
[1657975031.253187][45387:45392] CHIP:SC: Sent PBKDF param request
[1657975031.253191][45387:45392] CHIP:CTL: Setting thread operational dataset from parameters
[1657975031.253194][45387:45392] CHIP:CTL: Setting attestation nonce to random value
[1657975031.253200][45387:45392] CHIP:CTL: Setting CSR nonce to random value
[1657975031.253206][45387:45392] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1657975031.253246][45387:45393] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1657975031.253281][45387:45390] CHIP:DL: TRACE: Bus acquired for name C-b14b
[1657975031.256556][45387:45392] CHIP:DL: PlatformBlueZInit init success
[1657975031.259552][45387:45390] CHIP:BLE: BLE removing known devices.
[1657975031.266366][45387:45390] CHIP:BLE: BLE initiating scan.
[1657975031.877366][45387:45392] CHIP:DL: Long dispatch time: 624 ms, for event type 2
[1657975031.887840][45387:45390] CHIP:BLE: New device scanned: D5:3A:52:3B:61:E7
[1657975031.887860][45387:45390] CHIP:BLE: Device discriminator match. Attempting to connect.
[1657975031.892576][45387:45390] CHIP:BLE: Scan complete notification without an active scan.
[1657975032.039841][45387:45390] CHIP:DL: ConnectDevice complete
[1657975033.079154][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0001
[1657975033.079174][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079185][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0001
[1657975033.079191][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079198][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0001
[1657975033.079204][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079213][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0001
[1657975033.079219][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079227][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0001
[1657975033.079233][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079240][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0001
[1657975033.079246][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079256][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079262][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079273][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0001
[1657975033.079279][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079286][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0001
[1657975033.079293][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079299][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0001
[1657975033.079305][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079316][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079322][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079331][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079337][45387:45390] CHIP:DL: Char1 /org/bluez/hci0/dev_D5_3A_52_3B_61_E7/service0010
[1657975033.079348][45387:45390] CHIP:DL: New BLE connection 0x7f26ec037020, device D5:3A:52:3B:61:E7, path /org/bluez/hci0/dev_D5_3A_52_3B_61_E7
[1657975033.079390][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1657975033.079405][45387:45392] CHIP:IN: BleConnectionComplete: endPoint 0x55dd66577160
[1657975033.550204][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657975033.648555][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1657975033.648603][45387:45392] CHIP:BLE: subscribe complete, ep = 0x55dd66577160
[1657975033.649097][45387:45390] CHIP:DL: Indication received, conn = 0x7f26ec037020
[1657975033.649267][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657975033.649314][45387:45392] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1657975033.649330][45387:45392] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1657975033.649341][45387:45392] CHIP:BLE: local and remote recv window size = 5
[1657975033.649425][45387:45392] CHIP:IN: BLE EndPoint 0x55dd66577160 Connection Complete
[1657975033.744928][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657975034.041577][45387:45390] CHIP:DL: Indication received, conn = 0x7f26ec037020
[1657975034.041752][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657975034.041875][45387:45392] CHIP:IN: Received malformed unsecure packet with source 0x0000000000000000 destination 0x0000000000000000
[1657975036.718650][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657975039.187359][45387:45390] CHIP:DL: Indication received, conn = 0x7f26ec037020
[1657975039.187562][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657975041.826419][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657975044.413814][45387:45390] CHIP:DL: Indication received, conn = 0x7f26ec037020
[1657975044.413895][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657975047.090998][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657975049.677016][45387:45390] CHIP:DL: Indication received, conn = 0x7f26ec037020
[1657975049.677101][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657975052.355232][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657975054.945547][45387:45390] CHIP:DL: Indication received, conn = 0x7f26ec037020
[1657975054.945667][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657975057.590412][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657975060.177006][45387:45390] CHIP:DL: Indication received, conn = 0x7f26ec037020
[1657975060.177088][45387:45392] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657975061.253437][45387:45392] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
[1657975061.253495][45387:45392] CHIP:TOO: Secure Pairing Failed
[1657975061.253511][45387:45392] CHIP:DIS: Closing all BLE connections
[1657975061.253526][45387:45392] CHIP:IN: Clearing BLE pending packets.
[1657975061.253572][45387:45392] CHIP:BLE: Auto-closing end point's BLE connection.
[1657975061.253585][45387:45392] CHIP:DL: Closing BLE GATT connection (con 0x7f26ec037020)
[1657975061.253627][45387:45392] CHIP:TOO: Pairing Failure: ../../src/protocols/secure_channel/PASESession.cpp:245: CHIP Error 0x00000032: Timeout
[1657975061.253838][45387:45390] CHIP:DL: BluezDisconnect peer=D5:3A:52:3B:61:E7
[1657975061.254025][45387:45387] CHIP:CTL: Shutting down the commissioner
[1657975061.254059][45387:45387] CHIP:CTL: Shutting down the controller
[1657975061.254077][45387:45387] CHIP:CTL: Shutting down the commissioner
[1657975061.254088][45387:45387] CHIP:CTL: Shutting down the controller
[1657975061.254099][45387:45387] CHIP:IN: Expiring all connections for fabric 1!!
[1657975061.254142][45387:45387] CHIP:CTL: Shutting down the commissioner
[1657975061.254164][45387:45387] CHIP:CTL: Shutting down the controller
[1657975061.254182][45387:45387] CHIP:IN: Expiring all connections for fabric 2!!
[1657975061.254222][45387:45387] CHIP:CTL: Shutting down the commissioner
[1657975061.254241][45387:45387] CHIP:CTL: Shutting down the controller
[1657975061.254253][45387:45387] CHIP:IN: Expiring all connections for fabric 3!!
[1657975061.254275][45387:45387] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1657975061.256087][45387:45387] CHIP:DMG: IM WH moving to [Uninitialized]
[1657975061.256126][45387:45387] CHIP:DMG: IM WH moving to [Uninitialized]
[1657975061.256148][45387:45387] CHIP:DMG: IM WH moving to [Uninitialized]
[1657975061.256165][45387:45387] CHIP:DMG: IM WH moving to [Uninitialized]
[1657975061.256183][45387:45387] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1657975061.256251][45387:45387] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1657975061.256485][45387:45387] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-yr3lPa)
[1657975061.256988][45387:45387] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657975061.257036][45387:45387] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1657975061.257051][45387:45387] CHIP:DL: Inet Layer shutdown
[1657975061.257061][45387:45387] CHIP:DL: BLE shutdown
[1657975061.257752][45387:45387] CHIP:DL: System Layer shutdown
[1657975061.257849][45387:45387] CHIP:TOO: Run command failure: ../../src/protocols/secure_channel/PASESession.cpp:245: CHIP Error 0x00000032: Timeout