Hi,
I'm testing the Matter sample Door lock and coprocessor in NCS v2.2.0 on 2 nrf52840 hdks. with android CHIP tool 2.2.0 prebuilt apk
and i established the otbr on a notebook with ubuntu 22.04.1 lts in VM virtualbox.
first of all pushing the button on the door lock hdk to start advertising and then open android CHIP tool APP.
then i tapped PROVISION CHIP DEVICE WITH THREAD then scanning the QR code and then tapping save network.
then the commissioning process looks started in door lock hdk console, as following log.
I: nRF5 802154 radio initialized I: 4 Sectors of 4096 bytes I: alloc wra: 2, df8 I: data wra: 2, 328 ooting Zephyr OS build v3.2.99-ncs1 *** [1;I: Init CHIP stack 32muart:~$ : 225 [DL]BLE address: DB:3E:1F:C6:07:E0 mI: SoftDevice Controller build revision: I: 6d 90 41 2a 38 e8 ad 17 |m.A*8... I: 29 a5 03 38 39 27 d7 85 |)..89'.. I: 1f 85 d8 e1 |.... I: 247 [DL]OpenThread SED interval set to 1000ms I: 254 [DL]OpenThread started: OK I: 257 [DL]Setting OpenThread device type to SLEEPY END DEVICE I: 263 [SVR]Server initializing... D: 266 [FP]Initializing FabricTable from persistent storage I: 272 [TS]Last Known Good Time: 2023-02-13T17:13:47 I: 278 [DMG]AccessControl: initializing I: 281 [DMG]Examples::AccessControlDelegate::Init I: 286 [DMG]AccessControl: setting I: 289 [DMG]DefaultAclStorage: initializing I: 293 [DMG]DefaultAclStorage: 0 entries loaded D: 297 [IN]UDP::Init bind&listen port=5540 E: 301 [IN]SO_REUSEPORT failed: 109 D: 305 [IN]UDP::Init bound to port=5540 D: 308 [IN]BLEBase::Init - setting/overriding transport D: 313 [IN]TransportMgr initialized D: 321 [DL]Using Thread extended MAC for hostname. I: 327 [ZCL]Using ZAP configuration... D: 332 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0 I: 340 [DMG]AccessControlCluster: initializing D: 344 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 499d6207 D: 350 [DL]Boot reason: 1 D: 353 [ZCL]GeneralDiagnostics: OnDeviceReboot D: 357 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to 65075fb8 D: 364 [EVL]LogEvent event number: 0x00000000002C0000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000016B I: 377 [ZCL]Initiating Admin Commissioning cluster. I: 382 [ZCL]Door Lock server initialized D: 386 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to 215ba73e I: 392 [ZCL]Door Lock cluster initialized at endpoint #1 D: 397 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to e326f2dd D: 404 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to e326f2de D: 410 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to e326f2df D: 417 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to e326f2e0 D: 423 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to e326f2e1 D: 429 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to e326f2e2 D: 436 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to e326f2e3 D: 442 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to e326f2e4 I: 449 [DIS]Updating services using commissioning mode 0 D: 454 [DL]Using Thread extended MAC for hostname. D: 459 [DL]Using Thread extended MAC for hostname. I: 464 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0 E: 473 [DIS]Failed to advertise extended commissionable node: 3 D: 479 [DIS]Scheduling extended discovery timeout in 900s E: 484 [DIS]Failed to finalize service update: 1c I: 489 [DIS]Delaying proxy of operational discovery: missing delegate I: 495 [IN]CASE Server enabling CASE session setups D: 500 [IN]SecureSession[0x20003a10]: Allocated Type:2 LSID:42078 D: 506 [SC]Allocated SecureSession (0x20003a10) - waiting for Sigma1 msg I: 512 [SVR]Joining Multicast groups D: 515 [ZCL]Emitting StartUp event D: 519 [EVL]LogEvent event number: 0x00000000002C0001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000207 I: 533 [SVR]Server Listening... I: 536 [DL]Device Configuration: I: 539 [DL] Serial Number: 11223344556677889900 I: 544 [DL] Vendor Id: 65521 (0xFFF1) I: 547 [DL] Product Id: 32774 (0x8006) I: 551 [DL] Hardware Version: 0 I: 555 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 561 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 568 [DL] Manufacturing Date: (not set) I: 572 [DL] Device Type: 65535 (0xFFFF) I: 577 [SVR]SetupQRCode: [MT:8IXS142C00KA0648G00] I: 581 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 587 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A8IXS142C00KA0648G00 I: 596 [SVR]Manual pairing code: [34970112332] I: 601 [DL]CHIP task running I: 604 [DIS]Updating services using commissioning mode 0 D: 609 [DL]Using Thread extended MAC for hostname. D: 614 [DL]Using Thread extended MAC for hostname. I: 619 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0 E: 629 [DIS]Failed to advertise extended commissionable node: 3 E: 634 [DIS]Failed to finalize service update: 1c D: 639 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to e326f2e5 D: 3452 [IN]SecureSession[0x20003ac8]: Allocated Type:1 LSID:42079 D: 3458 [SC]Assigned local session key ID 42079 D: 3462 [SC]Waiting for PBKDF param request D: 3466 [DL]CHIPoBLE advertising set to on I: 3470 [DIS]Updating services using commissioning mode 1 D: 3475 [DL]Using Thread extended MAC for hostname. D: 3480 [DL]Using Thread extended MAC for hostname. I: 3486 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1 E: 3495 [DIS]Failed to advertise commissionable node: 3 E: 3500 [DIS]Failed to finalize service update: 1c I: 3507 [DL]CHIPoBLE advertising started I: 3512 [DL]NFC Tag emulation started I: 28215 [DL]BLE connection established (ConnId: 0x00) I: 28220 [DL]Current number of connections: 1/2 I: 28224 [DL]CHIPoBLE advertising stopped I: 28228 [DL]NFC Tag emulation stopped D: 30176 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 30183 [BLE]local and remote recv window sizes = 5 I: 30188 [BLE]selected BTP version 4 I: 30191 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 30266 [DL]ConnId: 0x00, New CCCD value: 0x0002 D: 30271 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) D: 30278 [IN]BLE EndPoint 0x2000fee0 Connection Complete I: 30284 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) D: 30491 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 30499 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 30507 [EM]>>> [E:29066r M:130869813] (U) Msg RX from 0:600E9C28BCB53575 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) D: 30519 [EM]Handling via exchange: 29066r, Delegate: 0x20005bf4 D: 30525 [SC]Received PBKDF param request D: 30528 [SC]Peer assigned session ID 18662 D: 30532 [SC]Found MRP parameters in the message D: 30537 [SC]Including MRP parameters in PBKDF param response I: 30543 [EM]<<< [E:29066r M:70889407] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 30555 [IN](U) Sending msg 70889407 to IP address 'BLE' D: 30560 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140) D: 30568 [SC]Sent PBKDF param response D: 30671 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 30807 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 30814 [EM]>>> [E:29066r M:130869814] (U) Msg RX from 0:600E9C28BCB53575 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) D: 30825 [EM]Found matching exchange: 29066r, Delegate: 0x20005bf4 D: 30831 [SC]Received spake2p msg1 I: 32741 [EM]<<< [E:29066r M:70889408] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 32752 [IN](U) Sending msg 70889408 to IP address 'BLE' D: 32758 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132) D: 32765 [SC]Sent spake2p msg2 E: 32768 [DL]Long dispatch time: 1962 ms, for event type 16388 D: 32831 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 32876 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 32884 [EM]>>> [E:29066r M:130869815] (U) Msg RX from 0:600E9C28BCB53575 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) D: 32895 [EM]Found matching exchange: 29066r, Delegate: 0x20005bf4 D: 32901 [SC]Received spake2p msg3 D: 32905 [SC]Sending status report. Protocol code 0, exchange 29066 I: 32911 [EM]<<< [E:29066r M:70889409] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 32922 [IN](U) Sending msg 70889409 to IP address 'BLE' D: 32928 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35) I: 32936 [SC]SecureSession[0x20003ac8]: Moving from state 'kEstablishing' --> 'kActive' D: 32944 [IN]SecureSession[0x20003ac8]: Activated - Type:1 LSID:42079 D: 32950 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:42079 PSID:18662! I: 32959 [SVR]Commissioning completed session establishment step I: 32966 [DIS]Updating services using commissioning mode 0 D: 32971 [DL]Using Thread extended MAC for hostname. D: 32976 [DL]Using Thread extended MAC for hostname. I: 32982 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0 E: 32991 [DIS]Failed to advertise extended commissionable node: 3 D: 32997 [DIS]Scheduling extended discovery timeout in 900s E: 33002 [DIS]Failed to finalize service update: 1c D: 33007 [DL]CHIPoBLE advertising set to off I: 33012 [SVR]Device completed Rendezvous process E: 33016 [DL]Long dispatch time: 140 ms, for event type 16388 D: 33022 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 33030 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 33038 [EM]>>> [E:29067r M:109076848] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 33049 [EM]Handling via exchange: 29067r, Delegate: 0x2000d8ac D: 33054 [IM]Received Read request D: 33061 [DMG]IM RH moving to [GeneratingReports] D: 33066 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 33074 [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty D: 33079 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1) D: 33088 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty D: 33093 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) D: 33103 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty D: 33108 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 33117 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty D: 33122 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 33131 [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty D: 33136 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 33145 [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty D: 33151 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D: 33160 [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty D: 33165 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0) D: 33174 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty D: 33179 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1) D: 33188 [DMG]<RE> Sending report (payload has 228 bytes)... I: 33195 [EM]<<< [E:29067r M:80071122] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 33205 [IN](S) Sending msg 80071122 on secure session with LSID: 42079 D: 33212 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 33220 [DMG]<RE> OnReportConfirm: NumReports = 0 D: 33224 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 33232 [DMG]IM RH moving to [AwaitingDestruction] D: 33237 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 33416 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 33424 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21) D: 33507 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 33514 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 33523 [EM]>>> [E:29068r M:109076849] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 33534 [EM]Handling via exchange: 29068r, Delegate: 0x2000d8ac D: 33540 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 I: 33548 [FS]GeneralCommissioning: Received ArmFailSafe (30s) D: 33554 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 499d6208 D: 33560 [DMG]Command handler moving to [ Preparing] D: 33565 [DMG]Command handler moving to [AddingComm] D: 33570 [DMG]Command handler moving to [AddedComma] D: 33575 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 33582 [EM]<<< [E:29068r M:80071123] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 33593 [IN](S) Sending msg 80071123 on secure session with LSID: 42079 D: 33599 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 33607 [DMG]Command handler moving to [CommandSen] D: 33612 [DMG]Command handler moving to [AwaitingDe] E: 33617 [DL]Long dispatch time: 103 ms, for event type 16388 D: 33687 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 33694 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 33703 [EM]>>> [E:29069r M:109076850] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 33714 [EM]Handling via exchange: 29069r, Delegate: 0x2000d8ac D: 33720 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 D: 33732 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 499d6209 D: 33738 [DMG]Command handler moving to [ Preparing] D: 33743 [DMG]Command handler moving to [AddingComm] D: 33748 [DMG]Command handler moving to [AddedComma] D: 33753 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 33760 [EM]<<< [E:29069r M:80071124] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 33771 [IN](S) Sending msg 80071124 on secure session with LSID: 42079 D: 33778 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 33786 [DMG]Command handler moving to [CommandSen] D: 33790 [DMG]Command handler moving to [AwaitingDe] E: 33795 [DL]Long dispatch time: 101 ms, for event type 16388 D: 33867 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 33874 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 33882 [EM]>>> [E:29070r M:109076851] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 33894 [EM]Handling via exchange: 29070r, Delegate: 0x2000d8ac D: 33900 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 33908 [ZCL]OpCreds: Certificate Chain request received for PAI D: 33914 [DMG]Command handler moving to [ Preparing] D: 33918 [DMG]Command handler moving to [AddingComm] D: 33923 [DMG]Command handler moving to [AddedComma] D: 33928 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 33937 [EM]<<< [E:29070r M:80071125] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 33948 [IN](S) Sending msg 80071125 on secure session with LSID: 42079 D: 33955 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 33963 [DMG]Command handler moving to [CommandSen] D: 33968 [DMG]Command handler moving to [AwaitingDe] D: 34046 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 34054 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 34181 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 34189 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48) D: 34272 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 34279 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 34287 [EM]>>> [E:29071r M:109076852] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 34299 [EM]Handling via exchange: 29071r, Delegate: 0x2000d8ac D: 34305 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 34313 [ZCL]OpCreds: Certificate Chain request received for DAC D: 34319 [DMG]Command handler moving to [ Preparing] D: 34323 [DMG]Command handler moving to [AddingComm] D: 34328 [DMG]Command handler moving to [AddedComma] D: 34333 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 34343 [EM]<<< [E:29071r M:80071126] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 34354 [IN](S) Sending msg 80071126 on secure session with LSID: 42079 D: 34360 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 34368 [DMG]Command handler moving to [CommandSen] D: 34373 [DMG]Command handler moving to [AwaitingDe] D: 34451 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 34459 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 34541 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 34549 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 76) D: 34631 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 34639 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 34648 [EM]>>> [E:29072r M:109076853] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 34659 [EM]Handling via exchange: 29072r, Delegate: 0x2000d8ac D: 34665 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 I: 34673 [ZCL]OpCreds: Received an AttestationRequest command I: 34710 [ZCL]OpCreds: AttestationRequest successful. D: 34714 [DMG]Command handler moving to [ Preparing] D: 34719 [DMG]Command handler moving to [AddingComm] D: 34724 [DMG]Command handler moving to [AddedComma] D: 34729 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 34740 [EM]<<< [E:29072r M:80071127] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 34750 [IN](S) Sending msg 80071127 on secure session with LSID: 42079 D: 34757 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 34765 [DMG]Command handler moving to [CommandSen] D: 34770 [DMG]Command handler moving to [AwaitingDe] E: 34774 [DL]Long dispatch time: 135 ms, for event type 16388 D: 34811 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 34819 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 35036 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 35044 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 235) D: 35126 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 35261 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 35270 [EM]>>> [E:29073r M:109076854] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 35281 [EM]Handling via exchange: 29073r, Delegate: 0x2000d8ac D: 35287 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 I: 35295 [ZCL]OpCreds: Received a CSRRequest command D: 35300 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0 I: 35494 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 35531 [ZCL]OpCreds: CSRRequest successful. D: 35535 [DMG]Command handler moving to [ Preparing] D: 35539 [DMG]Command handler moving to [AddingComm] D: 35544 [DMG]Command handler moving to [AddedComma] D: 35549 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 35558 [EM]<<< [E:29073r M:80071128] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 35569 [IN](S) Sending msg 80071128 on secure session with LSID: 42079 D: 35575 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 35583 [DMG]Command handler moving to [CommandSen] D: 35588 [DMG]Command handler moving to [AwaitingDe] E: 35593 [DL]Long dispatch time: 332 ms, for event type 16388 D: 35666 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 35674 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 138) D: 35936 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 35982 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 36071 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 36080 [EM]>>> [E:29074r M:109076855] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 36092 [EM]Handling via exchange: 29074r, Delegate: 0x2000d8ac D: 36098 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B I: 36106 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 36170 [ZCL]OpCreds: AddTrustedRootCertificate successful. D: 36176 [DMG]Command handler moving to [ Preparing] D: 36180 [DMG]Command handler moving to [AddingComm] D: 36185 [DMG]Command handler moving to [AddedComma] D: 36190 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 36197 [EM]<<< [E:29074r M:80071129] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 36209 [IN](S) Sending msg 80071129 on secure session with LSID: 42079 D: 36215 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68) D: 36223 [DMG]Command handler moving to [CommandSen] D: 36227 [DMG]Command handler moving to [AwaitingDe] E: 36232 [DL]Long dispatch time: 161 ms, for event type 16388 D: 36296 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 36304 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 36387 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 36396 [EM]>>> [E:29075r M:109076856] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 36407 [EM]Handling via exchange: 29075r, Delegate: 0x2000d8ac D: 36413 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 I: 36421 [ZCL]OpCreds: Received an AddNOC command I: 36428 [FP]Validating NOC chain I: 36490 [FP]NOC chain validation successful I: 36494 [FP]Added new fabric at index: 0x1 I: 36498 [FP]Assigned compressed fabric ID: 0x4F5810709105CA2C, node ID: 0x0000000000000017 I: 36507 [TS]Last Known Good Time: 2023-02-13T17:13:47 I: 36512 [TS]New proposed Last Known Good Time: 2021-06-10T00:00:00 I: 36518 [TS]Retaining current Last Known Good Time D: 36523 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 6c1ce07 D: 36529 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 6c1ce08 D: 36553 [EVL]LogEvent event number: 0x00000000002C0002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x0000000000008EC9 I: 36568 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 D: 36577 [DL]Using Thread extended MAC for hostname. I: 36581 [DIS]Advertise operational node 4F5810709105CA2C-0000000000000017 D: 36588 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 6c1ce09 D: 36595 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 6c1ce0a D: 36601 [DMG]Command handler moving to [ Preparing] D: 36606 [DMG]Command handler moving to [AddingComm] D: 36611 [DMG]Command handler moving to [AddedComma] I: 36616 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC D: 36622 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 36630 [EM]<<< [E:29075r M:80071130] (S) Msg TX to 1:FFFFFFFB00000000 [CA2C] --- Type 0001:09 (IM:InvokeCommandResponse) I: 36641 [IN](S) Sending msg 80071130 on secure session with LSID: 42079 D: 36647 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 36655 [DMG]Command handler moving to [CommandSen] D: 36660 [DMG]Command handler moving to [AwaitingDe] E: 36664 [DL]Long dispatch time: 278 ms, for event type 16388 D: 36701 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 36709 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 36718 [EM]>>> [E:29076r M:109076857] (S) Msg RX from 1:FFFFFFFB00000000 [CA2C] --- Type 0001:08 (IM:InvokeCommandRequest) D: 36729 [EM]Handling via exchange: 29076r, Delegate: 0x2000d8ac D: 36735 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003 D: 36749 [DMG]Command handler moving to [ Preparing] D: 36754 [DMG]Command handler moving to [AddingComm] D: 36759 [DMG]Command handler moving to [AddedComma] D: 36763 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 499d620a D: 36770 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 36777 [EM]<<< [E:29076r M:80071131] (S) Msg TX to 1:FFFFFFFB00000000 [CA2C] --- Type 0001:09 (IM:InvokeCommandResponse) I: 36788 [IN](S) Sending msg 80071131 on secure session with LSID: 42079 D: 36795 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 36803 [DMG]Command handler moving to [CommandSen] D: 36808 [DMG]Command handler moving to [AwaitingDe] E: 36812 [DL]Long dispatch time: 103 ms, for event type 16388 D: 36882 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 36889 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 36898 [EM]>>> [E:29077r M:109076858] (S) Msg RX from 1:FFFFFFFB00000000 [CA2C] --- Type 0001:08 (IM:InvokeCommandRequest) D: 36909 [EM]Handling via exchange: 29077r, Delegate: 0x2000d8ac D: 36915 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006 D: 36962 [DMG]Decreasing reference count for CommandHandler, remaining 1 D: 36968 [DL]OpenThread State Changed (Flags: 0x1006c100) D: 36973 [DL] Network Name: OpenThread D: 36978 [DL] PAN Id: 0x1234 D: 36981 [DL] Extended PAN Id: 0x1111111122222222 D: 36985 [DL] Channel: 15 D: 36988 [DL] Mesh Prefix: fdde:ad00:beef::/64 D: 36993 [DL]OpenThread State Changed (Flags: 0x0100103d) D: 36998 [DL] Device Role: DETACHED D: 37001 [DL] Thread Unicast Addresses: D: 37005 [DL] fdde:ad00:beef::ff:fe00:480a/64 valid rloc D: 37011 [DL] fdde:ad00:beef:0:89a:cfb4:9767:89b2/64 valid D: 37017 [DL] fe80::a045:62b7:f0d1:aa68/64 valid preferred D: 39397 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 39491 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41935 [DL]OpenThread State Changed (Flags: 0x10000040) D: 41966 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 43093 [DL]SRP Client was started, detected server: fd66:794b:79b6:5d20:6ff9:e0b5:5c09:ca54 D: 43102 [DL]OpenThread State Changed (Flags: 0x301132b7) D: 43108 [DL] Device Role: CHILD D: 43111 [DL] Network Name: OpenThreadDemo D: 43115 [DL] PAN Id: 0x1234 D: 43118 [DL] Extended PAN Id: 0x1111111122222222 D: 43122 [DL] Channel: 15 D: 43125 [DL] Mesh Prefix: fd66:794b:79b6:5d20::/64 D: 43130 [DL] Partition Id: 0x35D77651 D: 43133 [DL] Thread Unicast Addresses: D: 43138 [DL] fda7:668a:97:1:c8fb:34a8:441e:a708/64 valid preferred D: 43144 [DL] fd66:794b:79b6:5d20:0:ff:fe00:4801/64 valid rloc D: 43151 [DL] fd66:794b:79b6:5d20:89a:cfb4:9767:89b2/64 valid D: 43157 [DL] fe80::a045:62b7:f0d1:aa68/64 valid preferred D: 43163 [DL]OpenThread State Changed (Flags: 0x00000001) D: 43169 [DL] Thread Unicast Addresses: D: 43172 [DL] fda7:668a:97:1:c8fb:34a8:441e:a708/64 valid preferred D: 43179 [DL] fd66:794b:79b6:5d20:0:ff:fe00:4801/64 valid rloc D: 43186 [DL] fd66:794b:79b6:5d20:89a:cfb4:9767:89b2/64 valid D: 43192 [DL] fe80::a045:62b7:f0d1:aa68/64 valid preferred D: 43198 [DMG]Command handler moving to [ Preparing] D: 43205 [DMG]Command handler moving to [AddingComm] D: 43210 [DMG]Command handler moving to [AddedComma] D: 43215 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 499d620b D: 43222 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 43230 [EM]<<< [E:29077r M:80071132] (S) Msg TX to 1:FFFFFFFB00000000 [CA2C] --- Type 0001:09 (IM:InvokeCommandResponse) I: 43242 [IN](S) Sending msg 80071132 on secure session with LSID: 42079 D: 43249 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70) D: 43257 [DMG]Command handler moving to [CommandSen] D: 43261 [DMG]Command handler moving to [AwaitingDe] D: 43266 [DL]Using Thread extended MAC for hostname. I: 43271 [DIS]Advertise operational node 4F5810709105CA2C-0000000000000017 I: 43278 [SVR]Operational advertising enabled D: 43316 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 43832 [DL]SRP update succeeded I: 43835 [DIS]Setting operational delegate post init I: 43843 [SWU]Stopping the watchdog timer I: 43847 [SWU]Starting the periodic query timer, timeout: 86400 seconds I: 43854 [DIS]Updating services using commissioning mode 0 D: 43859 [DL]Using Thread extended MAC for hostname. I: 43864 [DIS]Advertise operational node 4F5810709105CA2C-0000000000000017 I: 43871 [DL]advertising srp service: 4F5810709105CA2C-0000000000000017._matter._tcp D: 43879 [DL]Using Thread extended MAC for hostname. I: 43884 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0 I: 43894 [DL]advertising srp service: B631BB1655664801._matterc._udp D: 43900 [DMG]Endpoint 0, Cluster 0x0000_002A update version to bd0628c0 D: 43907 [DMG]Endpoint 0, Cluster 0x0000_002A update version to bd0628c1 D: 45421 [DL]SRP update succeeded D: 45836 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 48343 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 48401 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 50876 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 53383 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 53441 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 55960 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 58468 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 58525 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 61000 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 63508 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) I: 63554 [FS]Fail-safe timer expired E: 63557 [SVR]Failsafe timer expired D: 63560 [IN]SecureSession[0x20003ac8]: MarkForEviction Type:1 LSID:42079 I: 63568 [SC]SecureSession[0x20003ac8]: Moving from state 'kActive' --> 'kPendingEviction' D: 63576 [IN]SecureSession[0x20003ac8]: Released - Type:1 LSID:42079 E: 63582 [SVR]Commissioning failed (attempt 1): 32 D: 63586 [IN]Clearing BLE pending packets. I: 63590 [BLE]Releasing end point's BLE connection back to application. I: 63597 [DL]Closing BLE GATT connection (ConnId 00) D: 63604 [IN]SecureSession[0x20003ac8]: Allocated Type:1 LSID:42080 D: 63610 [SC]Assigned local session key ID 42080 D: 63615 [SC]Waiting for PBKDF param request D: 63619 [DL]CHIPoBLE advertising set to on I: 63623 [DIS]Updating services using commissioning mode 1 D: 63628 [DL]Using Thread extended MAC for hostname. I: 63633 [DIS]Advertise operational node 4F5810709105CA2C-0000000000000017 D: 63640 [DL]Using Thread extended MAC for hostname. I: 63645 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1 I: 63655 [DL]advertising srp service: B631BB1655664801._matterc._udp E: 63662 [ZCL]OpCreds: Got FailSafeTimerExpired E: 63666 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! D: 63673 [IN]Expiring all sessions for fabric 0x1!! E: 63677 [FP]Reverting pending fabric data for fabric 0x1 D: 63683 [EVL]LogEvent event number: 0x00000000002C0003 priority: 1, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000000F8C2 D: 63697 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet E: 63703 [FP]Warning: metadata not found during delete of fabric 0x1 I: 63716 [FP]Fabric (0x1) deleted. I: 63719 [ZCL][OnFabricRemoved] Handling a fabric removal from the door lock server [endpointId=1,fabricIndex=1] I: 63729 [ZCL]Getting lock user 1: available I: 63733 [ZCL]Getting lock user 2: available I: 63737 [ZCL]Getting lock user 3: available I: 63741 [ZCL]Getting lock user 4: available I: 63745 [ZCL]Getting lock user 5: available I: 63749 [ZCL]Getting lock user 6: available I: 63753 [ZCL]Getting lock user 7: available I: 63757 [ZCL]Getting lock user 8: available I: 63761 [ZCL]Getting lock user 9: available I: 63765 [ZCL]Getting lock user 10: available I: 63770 [ZCL]Getting lock credential 1: available I: 63774 [ZCL]Getting lock credential 2: available I: 63779 [ZCL]Getting lock credential 3: available I: 63783 [ZCL]Getting lock credential 4: available I: 63788 [ZCL]Getting lock credential 5: available I: 63792 [ZCL]Getting lock credential 6: available I: 63797 [ZCL]Getting lock credential 7: available I: 63802 [ZCL]Getting lock credential 8: available I: 63806 [ZCL]Getting lock credential 9: available I: 63811 [ZCL]Getting lock credential 10: available E: 63815 [ZCL][clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=0,credentialIndex=0,fabricIdToRemove=1] I: 63832 [ZCL]OpCreds: Fabric index 0x1 was removed D: 63838 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 6c1ce0b D: 63844 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 6c1ce0c I: 63869 [TS]Pending Last Known Good Time: 2023-02-13T17:13:47 I: 63875 [TS]Previous Last Known Good Time: 2023-02-13T17:13:47 I: 63881 [TS]Reverted Last Known Good Time to previous value D: 63886 [EVL]LogEvent event number: 0x00000000002C0004 priority: 1, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000000F98E D: 63900 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet E: 63907 [FP]Warning: metadata not found during delete of fabric 0x1 E: 63915 [ZCL]OpCreds: failed to delete fabric at index 1: d8 D: 63921 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 499d620c D: 63928 [ZCL]Failsafe timeout, tell platform driver to revert network credentials. I: 63935 [NP]Reverting Thread operational dataset E: 63947 [DL]Long dispatch time: 390 ms, for event type 32782 I: 63952 [FS]Fail-safe cleanly disarmed D: 63956 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) E: 63964 [BLE]no endpoint for BLE sent data ack D: 63969 [DL]OpenThread State Changed (Flags: 0x11002046) D: 63974 [DL] Device Role: DISABLED D: 63978 [DL] Thread Unicast Addresses: D: 63981 [DL] fda7:668a:97:1:c8fb:34a8:441e:a708/64 valid preferred I: 63989 [DL]BLE GAP connection terminated (reason 0x16) I: 63994 [DL]Current number of connections: 0/2 I: 64000 [DL]CHIPoBLE advertising started I: 64005 [DL]NFC Tag emulation started I: 94004 [DL]CHIPoBLE advertising mode changed to slow
during this processing, i found the door lock had joined the thread network as child and it also responded my ping from ubuntu Otbr
however, after the log in hdk console stopped, android CHIP tool showed commissioning failed and keep in a white screen.
and the door lock hdk no longer responded pings from Otbr. but the Otbr can still find the child in topology for few minutes before it disappeared.
