Hello,
I am struggling to commission a light bulb matter sample device (nrf52840dk) with the CHIP tool running on my Linux laptop. I set up an OpenThread Border Router with a RaspberryPi 4 and another nrf52840dk as RCP. The Thread seems to be fine as I can DNS services as shown on the official OpenThread documentation.
During commissioning something fails during BLE packets exchange I believe.
I am running latest CHIP release while the Matter light bulb demo was built a while ago. The RCP has been built with a more recent OpenThread library commit than the Matter example. I don't know if it has to do with a compatibility issue.
What loos suspicious is this line in the CHIP tool log:
[1657975034.041875][45387:45392] CHIP:IN: Received malformed unsecure packet with source 0x0000000000000000 destination 0x0000000000000000
I hope you can help understanding what is going on by the logs attached. These logs are from the CHIP tool and the Matter sample board.
Thank you.
./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
Starting CHIP task I: Init Thread stack I: 247 [DL]OpenThread started: OK I: 250 [DL]Setting OpenThread device type to MINIMAL END DEVICE I: 258 [ZCL]Using ZAP configuration... I: 262 [ZCL]Initiating Admin Commissioning cluster. I: 267 [ZCL]OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. D: 275 [DIS]Set the fabric pairing table delegate I: 280 [ZCL]0xaf2adep 0 clus 0x0000_0028 attr 0x0000_000F not supported E: 286 [ZCL]Error setting Serial Number String: 0x86 I: 291 [ZCL]Cluster OnOff: attribute OnOff set to 0 I: 296 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254 D: 302 [DIS]Init fabric pairing table with server storage D: 309 [IN]UDP::Init bind&listen port=5540 D: 313 [IN]UDP::Init bound to port=5540 D: 317 [IN]TransportMgr initialized D: 326 [SC]Assigned local session key ID 1 D: 329 [SC]Waiting for PBKDF param request D: 333 [DL]CHIPoBLE advertising set to on D: 337 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=1 D: 342 [DL]Using Thread extended MAC for hostname. I: 347 [DIS]Failed to find a valid admin pairing. Node ID unknown I: 353 [DIS]Start dns-sd server - no current nodeId D: 357 [DL]Using Thread extended MAC for hostname. I: 362 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15 E: 371 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003 D: 379 [DIS]Scheduling Discovery timeout in secs=900 E: 383 [DIS]Failed to finalize service update: Error CHIP:0x0000001C D: 390 [DIS]DNS-SD StartServer modeHasValue=0 modeValue=0 D: 395 [DL]Using Thread extended MAC for hostname. I: 399 [DIS]Failed to find a valid admin pairing. Node ID unknown I: 405 [DIS]Start dns-sd server - no current nodeId D: 410 [DL]Using Thread extended MAC for hostname. I: 415 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15 E: 423 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003 D: 431 [DIS]Scheduling Discovery timeout in secs=900 E: 436 [DIS]Failed to finalize service update: Error CHIP:0x0000001C I: 442 [IN]CASE Server enabling CASE session setups D: 447 [DL]Using Thread extended MAC for hostname. I: 451 [SVR]Server Listening... I: 454 [DL]Device Configuration: I: 457 [DL] Serial Number: TEST_SN I: 461 [DL] Vendor Id: 9050 (0x235A) I: 464 [DL] Product Id: 20044 (0x4E4C) I: 468 [DL] Hardware Version: 0 I: 471 [DL] Setup Pin Code: 20202021 I: 474 [DL] Setup Discriminator: 3840 (0xF00) I: 479 [DL] Manufacturing Date: (not set) I: 483 [DL] Device Type: 65535 (0xFFFF) I: 487 [SVR]SetupQRCode: [MT:Y3.13OTB00KA0648G00] I: 491 [SVR]Copy/paste the below URL in a browser to see the QR Code: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3AY3.13OTB00KA0648G00 I: 506 [SVR]Manual pairing code: [34970112332] I: 510 [SVR]Long manual pairing code: [749701123309050200447] D: 516 [IN]UDP::Init bind&listen port=12345 D: 520 [IN]UDP::Init bound to port=12345 D: 524 [DL]CHIP task running I: 529 [DL]CHIPoBLE advertising started I: 532 [ZCL]GeneralDiagnosticsDelegate: OnDeviceRebooted I: 540 [DL]NFC Tag emulation started I: 10487 [DL]BLE connection established (ConnId: 0x00) I: 10492 [DL]Current number of connections: 1/1 I: 10496 [DL]CHIPoBLE advertising stopped I: 10500 [DL]NFC Tag emulation stopped D: 12047 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 12053 [BLE]local and remote recv window sizes = 5 I: 12057 [BLE]selected BTP version 4 I: 12061 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 12144 [DL]ConnId: 0x00, New CCCD value: 0x0001 D: 12149 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6) D: 12155 [IN]BLE EndPoint 0x20007920 Connection Complete I: 12160 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) D: 12242 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 12248 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 12255 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:2493225122 on exchange 54953r D: 12265 [EM]Handling via exchange: 54953r, Delegate: 0x20005458 D: 12270 [SC]Received PBKDF param request D: 12274 [SC]Peer assigned session ID 39540 D: 12278 [SC]Found MRP parameters in the message D: 12283 [SC]Including MRP parameters in PBKDF param response I: 12510 [IN]Prepared unauthenticated message 0x20026c10 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 54953r with MessageCounter:2083741720. I: 12525 [IN]Sending unauthenticated msg 0x20026c10 with MessageCounter:2083741720 to 0x0000000000000000 at monotonic time: 12525 msec D: 12537 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 130) D: 12543 [SC]Sent PBKDF param response E: 12547 [DL]Long dispatch time: 299 ms, for event type 16388 D: 12631 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 15215 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 17721 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 17746 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 20356 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 22862 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 22891 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 25621 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 28128 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 28156 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 30886 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 33393 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 33421 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 36121 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 38627 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 38656 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 39811 [DL]ConnId: 0x00, New CCCD value: 0x0000 D: 39815 [IN]Clearing BLE pending packets. I: 39819 [BLE]Releasing end point's BLE connection back to application. I: 39826 [DL]Closing BLE GATT connection (ConnId 00) I: 39856 [DL]BLE GAP connection terminated (reason 0x16) I: 39861 [DL]Current number of connections: 0/1 I: 39867 [DL]CHIPoBLE advertising started I: 39871 [DL]NFC Tag emulation started E: 42509 [SC]PASESession timed out while waiting for a response from the peer. Expected message type was 34 E: 42519 [SVR]Commissioning failed (attempt 1): Error CHIP:0x00000032 D: 42526 [SC]Assigned local session key ID 2 D: 42530 [SC]Waiting for PBKDF param request D: 42534 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=1 D: 42539 [DL]Using Thread extended MAC for hostname. I: 42544 [DIS]Failed to find a valid admin pairing. Node ID unknown I: 42550 [DIS]Start dns-sd server - no current nodeId D: 42555 [DL]Using Thread extended MAC for hostname. I: 42560 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15 E: 42569 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003 D: 42577 [DIS]Scheduling Discovery timeout in secs=900 E: 42582 [DIS]Failed to finalize service update: Error CHIP:0x0000001C I: 69871 [DL]CHIPoBLE advertising mode changed to slow
