I am trying to test template sample application with nRF52840DK and see that commissioning fails
My environment:
nRF connect sdk: v2.3.0
nRF connect toolchain: v2.3.0
chip-tool running on ubuntu
border router: Raspberry Pi with nRf52840 Dongle
I see that BLE connection is successful, but fails with error -Failed to perform commissioning step 18
Please see the attached file for logs
Appreciate your quick help
Thanks,
Mahesh
: 92797EEA6C7282EA._matterc._udp E: 89539 [ZCL]OpCreds: Got FailSafeTimerExpired E: 89543 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! D: 89549 [IN]Expiring all sessions for fabric 0x1!! E: 89554 [FP]Reverting pending fabric data for fabric 0x1 D: 89559 [EVL]LogEvent event number: 0x0000000000000003 priority: 1, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x0000000000015DD7 D: 89573 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet E: 89580 [FP]Warning: metadata not found during delete of fabric 0x1 I: 89651 [FP]Fabric (0x1) deleted. I: 89655 [ZCL]OpCreds: Fabric index 0x1 was removed D: 89660 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0e2f1e3 D: 89667 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0e2f1e4 I: 89832 [TS]Pending Last Known Good Time: 2023-02-18T10:14:41 I: 89838 [TS]Previous Last Known Good Time: 2023-02-18T10:14:41 I: 89844 [TS]Reverted Last Known Good Time to previous value D: 89850 [EVL]LogEvent event number: 0x0000000000000004 priority: 1, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x0000000000015EF9 D: 89864 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet E: 89870 [FP]Warning: metadata not found during delete of fabric 0x1 E: 89879 [ZCL]OpCreds: failed to delete fabric at index 1: d8 D: 89884 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to b98af9cc D: 89891 [ZCL]Failsafe timeout, tell platform driver to revert network credentials. I: 89898 [NP]Reverting Thread operational dataset E: 89911 [DL]Long dispatch time: 460 ms, for event type 32782 I: 89916 [FS]Fail-safe cleanly disarmed I: 89922 [DL]CHIPoBLE advertising started D: 89926 [DL]OpenThread State Changed (Flags: 0x11002046) D: 89931 [DL] Device Role: DISABLED D: 89934 [DL] Thread Unicast Addresses: D: 89938 [DL] fd6a:8c75:12d3:1:2d9d:1522:2c95:e401/64 valid preferred D: 89946 [DL]OpenThread State Changed (Flags: 0x10000000) I: 119926 [DL]CHIPoBLE advertising mode changed to slow I: nRF5 802154 radio initialized I: 4 Sectors of 4096 bytes I: alloc wra: 3, 940 I: data wra: 3, 84c uart:~$ *** Booting Zephyr OS build v3.2.99-ncs2 *** I: Init CHIP stack I: 221 [DL]BLE address: F7:C4:D2:DA:E3:6F I: 232 [DL]OpenThread started: OK I: 235 [DL]Setting OpenThread device type to MINIMAL END DEVICE I: 241 [SVR]Server initializing... I: 244 [TS]Last Known Good Time: 2023-02-18T10:14:41 I: 249 [TS]Setting Last Known Good Time to firmware build time 2023-03-09T08:28:35 I: 259 [DMG]AccessControl: initializing I: 262 [DMG]Examples::AccessControlDelegate::Init I: 266 [DMG]AccessControl: setting I: 270 [DMG]DefaultAclStorage: initializing I: 273 [DMG]DefaultAclStorage: 0 entries loaded D: 278 [IN]UDP::Init bind&listen port=5540 E: 281 [IN]SO_REUSEPORT failed: 109 D: 285 [IN]UDP::Init bound to port=5540 D: 288 [IN]BLEBase::Init - setting/overriding transport D: 293 [IN]TransportMgr initialized I: 303 [ZCL]Using ZAP configuration... I: 308 [DMG]AccessControlCluster: initializing I: 312 [ZCL]Initiating Admin Commissioning cluster. D: 319 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:25692 I: 325 [DIS]Updating services using commissioning mode 1 I: 331 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 E: 340 [DIS]Failed to advertise commissionable node: 3 E: 345 [DIS]Failed to finalize service update: 1c I: 349 [DIS]Updating services using commissioning mode 1 I: 355 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 E: 364 [DIS]Failed to advertise commissionable node: 3 E: 369 [DIS]Failed to finalize service update: 1c I: 373 [DIS]Delaying proxy of operational discovery: missing delegate I: 379 [IN]CASE Server enabling CASE session setups D: 384 [IN]SecureSession[0x20003608]: Allocated Type:2 LSID:25693 I: 390 [SVR]Joining Multicast groups I: 393 [SVR]Server Listening... I: 396 [DL]Device Configuration: I: 399 [DL] Serial Number: 11223344556677889900 I: 404 [DL] Vendor Id: 65521 (0xFFF1) I: 407 [DL] Product Id: 32768 (0x8000) I: 411 [DL] Hardware Version: 0 I: 415 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 420 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 427 [DL] Manufacturing Date: (not set) I: 431 [DL] Device Type: 65535 (0xFFFF) I: 436 [SVR]SetupQRCode: [MT:Y.K9042C00KA0648G00] I: 440 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 446 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00 I: 455 [SVR]Manual pairing code: [34970112332] I: 460 [DL]CHIP task running I: 465 [DL]CHIPoBLE advertising started I: 20280 [DL]BLE connection established (ConnId: 0x00) I: 20285 [DL]Current number of connections: 1/1 I: 20289 [DL]CHIPoBLE advertising stopped I: 21882 [BLE]local and remote recv window sizes = 5 I: 21886 [BLE]selected BTP version 4 I: 21890 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 21972 [IN]BLE EndPoint 0x2000fd28 Connection Complete I: 21977 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) I: 22063 [EM]>>> [E:32398r M:133325430] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) I: 22076 [EM]<<< [E:32398r M:103602529] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 22087 [IN](U) Sending msg 103602529 to IP address 'BLE' I: 22198 [EM]>>> [E:32398r M:133325431] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) I: 24073 [EM]<<< [E:32398r M:103602530] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 24084 [IN](U) Sending msg 103602530 to IP address 'BLE' E: 24089 [DL]Long dispatch time: 1891 ms, for event type 16388 I: 24223 [EM]>>> [E:32398r M:133325432] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) I: 24234 [EM]<<< [E:32398r M:103602531] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 24245 [IN](U) Sending msg 103602531 to IP address 'BLE' I: 24252 [SC]SecureSession[0x20003550]: Moving from state 'kEstablishing' --> 'kActive' D: 24259 [IN]SecureSession[0x20003550]: Activated - Type:1 LSID:25692 D: 24266 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:25692 PSID:56322! I: 24275 [SVR]Commissioning completed session establishment step I: 24281 [DIS]Updating services using commissioning mode 0 I: 24287 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 E: 24296 [DIS]Failed to advertise extended commissionable node: 3 D: 24302 [DIS]Scheduling extended discovery timeout in 900s E: 24307 [DIS]Failed to finalize service update: 1c I: 24312 [SVR]Device completed Rendezvous process I: 24319 [EM]>>> [E:32399r M:259258149] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 24329 [IM]Received Read request I: 24338 [EM]<<< [E:32399r M:182183003] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 24348 [IN](S) Sending msg 182183003 on secure session with LSID: 25692 I: 24494 [EM]>>> [E:32400r M:259258150] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 24505 [FS]GeneralCommissioning: Received ArmFailSafe (60s) I: 24512 [EM]<<< [E:32400r M:182183004] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 24523 [IN](S) Sending msg 182183004 on secure session with LSID: 25692 I: 24584 [EM]>>> [E:32401r M:259258151] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 24597 [EM]<<< [E:32401r M:182183005] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 24608 [IN](S) Sending msg 182183005 on secure session with LSID: 25692 I: 24674 [EM]>>> [E:32402r M:259258152] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 24685 [ZCL]OpCreds: Certificate Chain request received for PAI I: 24694 [EM]<<< [E:32402r M:182183006] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 24705 [IN](S) Sending msg 182183006 on secure session with LSID: 25692 I: 24944 [EM]>>> [E:32403r M:259258153] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 24955 [ZCL]OpCreds: Certificate Chain request received for DAC I: 24964 [EM]<<< [E:32403r M:182183007] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 24975 [IN](S) Sending msg 182183007 on secure session with LSID: 25692 I: 25214 [EM]>>> [E:32404r M:259258154] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 25226 [ZCL]OpCreds: Received an AttestationRequest command I: 25262 [ZCL]OpCreds: AttestationRequest successful. I: 25270 [EM]<<< [E:32404r M:182183008] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 25281 [IN](S) Sending msg 182183008 on secure session with LSID: 25692 I: 25619 [EM]>>> [E:32405r M:259258155] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 25630 [ZCL]OpCreds: Received a CSRRequest command I: 25820 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 25856 [ZCL]OpCreds: CSRRequest successful. I: 25862 [EM]<<< [E:32405r M:182183009] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 25873 [IN](S) Sending msg 182183009 on secure session with LSID: 25692 E: 25880 [DL]Long dispatch time: 262 ms, for event type 16388 I: 26204 [EM]>>> [E:32406r M:259258156] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 26216 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 26279 [ZCL]OpCreds: AddTrustedRootCertificate successful. I: 26285 [EM]<<< [E:32406r M:182183010] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 26296 [IN](S) Sending msg 182183010 on secure session with LSID: 25692 E: 26303 [DL]Long dispatch time: 101 ms, for event type 16388 I: 26656 [EM]>>> [E:32407r M:259258157] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 26667 [ZCL]OpCreds: Received an AddNOC command I: 26674 [FP]Validating NOC chain I: 26792 [FP]NOC chain validation successful I: 26796 [FP]Added new fabric at index: 0x1 I: 26800 [FP]Assigned compressed fabric ID: 0x78D8657DCCA52CBD, node ID: 0x0000000000000001 I: 26808 [TS]Last Known Good Time: 2023-03-09T08:28:35 I: 26813 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00 I: 26819 [TS]Retaining current Last Known Good Time I: 27015 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 I: 27024 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001 I: 27030 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC I: 27038 [EM]<<< [E:32407r M:182183011] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse) I: 27048 [IN](S) Sending msg 182183011 on secure session with LSID: 25692 E: 27055 [DL]Long dispatch time: 402 ms, for event type 16388 I: 27106 [EM]>>> [E:32408r M:259258158] (S) Msg RX from 1:FFFFFFFB00000000 [2CBD] --- Type 0001:08 (IM:InvokeCommandRequest) I: 27123 [EM]<<< [E:32408r M:182183012] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse) I: 27134 [IN](S) Sending msg 182183012 on secure session with LSID: 25692 I: 27194 [EM]>>> [E:32409r M:259258159] (S) Msg RX from 1:FFFFFFFB00000000 [2CBD] --- Type 0001:08 (IM:InvokeCommandRequest) I: 28666 [DL]SRP Client was started, detected server: fdde:ad00:beef:0000:4b85:0af3:6b38:60d2 I: 28679 [EM]<<< [E:32409r M:182183013] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse) I: 28690 [IN](S) Sending msg 182183013 on secure session with LSID: 25692 I: 28697 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001 I: 28704 [SVR]Operational advertising enabled I: 29450 [DIS]Setting operational delegate post init I: 29458 [SWU]Stopping the watchdog timer I: 29462 [SWU]Starting the periodic query timer, timeout: 86400 seconds I: 29468 [DIS]Updating services using commissioning mode 0 I: 29473 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001 I: 29480 [DL]advertising srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp I: 29489 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 I: 29499 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp D: 73766 [IN]Clearing BLE pending packets. I: 73770 [BLE]Releasing end point's BLE connection back to application. I: 73776 [DL]Closing BLE GATT connection (ConnId 00) I: 73901 [DL]BLE GAP connection terminated (reason 0x16) I: 73906 [DL]Current number of connections: 0/1 I: 84511 [FS]Fail-safe timer expired E: 84514 [SVR]Failsafe timer expired D: 84518 [IN]SecureSession[0x20003550]: MarkForEviction Type:1 LSID:25692 I: 84524 [SC]SecureSession[0x20003550]: Moving from state 'kActive' --> 'kPendingEviction' D: 84532 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:25692 E: 84538 [SVR]Commissioning failed (attempt 1): 32 D: 84545 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:25694 I: 84551 [DIS]Updating services using commissioning mode 1 I: 84556 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001 I: 84564 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 I: 84574 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp E: 84580 [ZCL]OpCreds: Got FailSafeTimerExpired E: 84584 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! D: 84591 [IN]Expiring all sessions for fabric 0x1!! E: 84595 [FP]Reverting pending fabric data for fabric 0x1 E: 84601 [FP]Warning: metadata not found during delete of fabric 0x1 I: 84612 [FP]Fabric (0x1) deleted. I: 84615 [ZCL]OpCreds: Fabric index 0x1 was removed I: 84620 [DIS]Updating services using commissioning mode 1 I: 84626 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 I: 84635 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp I: 84642 [DL]removing srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp I: 84769 [TS]Pending Last Known Good Time: 2023-03-09T08:28:35 I: 84775 [TS]Previous Last Known Good Time: 2023-03-09T08:28:35 I: 84781 [TS]Reverted Last Known Good Time to previous value E: 84787 [FP]Warning: metadata not found during delete of fabric 0x1 E: 84795 [ZCL]OpCreds: failed to delete fabric at index 1: d8 I: 84801 [NP]Reverting Thread operational dataset E: 84813 [DL]Long dispatch time: 299 ms, for event type 32782 I: 84818 [FS]Fail-safe cleanly disarmed I: 84823 [DL]CHIPoBLE advertising started I: 114827 [DL]CHIPoBLE advertising mode changed to slow I: 114834 [DL]CHIPoBLE advertising started I: 900318 [SVR]Closing pairing window D: 900321 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:25694 I: 900327 [DIS]Updating services using commissioning mode 0 I: 900333 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 I: 900343 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp D: 900349 [DIS]Scheduling extended discovery timeout in 900s I: 900354 [DL]removing srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp I: 900362 [DL]CHIPoBLE advertising stopped