îgçïI: Factory Reset Triggered. Release button within 3000ms to cancel. I: Factory Reset triggered D: 143464 [ZCL]Emitting ShutDown event D: 143468 [EVL]LogEvent event number: 0x0000000000020002 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x1 Sys timestamp: 0x000000000002306C D: 143482 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet I: 143488 [DL]Performing factory reset I: 143512 [DL]Erasing Thread persistent info... I: nRF5 802154 radio initialized I: 4 Sectors of 4096 bytes I: alloc wra: 1, e78 I: data wra: 1, 5c *** Booting Zephyr OS build v3.0.99-ncs1 *** I: Init CHIP stack I: Swap type: none D: 131 [DL]Boot reason: 6 uart:~$ I: 235 [DL]BLE address: E6:4D:57:2E:84:51 I: SoftDevice Controller build revision: I: 33 78 2a 18 20 f5 61 61 |3x*. .aa I: a6 8b 77 60 62 83 39 2a |..w`b.9* I: 7c f1 14 e4 ||... I: 260 [DL]OpenThread started: OK I: 263 [DL]Setting OpenThread device type to ROUTER I: 268 [SVR]Server initializing... D: 272 [DIS]Init fabric pairing table with server storage 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 I: 297 [ZCL]Using ZAP configuration... I: 302 [DMG]AccessControlCluster: initializing I: 306 [ZCL]Initiating Admin Commissioning cluster. D: 311 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 6fa44934 I: 317 [ZCL]OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. D: 325 [DIS]Add fabric pairing table delegate D: 330 [DMG]Endpoint 0, Cluster 0x0000_0004 update version to 5a7cd7dc E: 336 [ZCL]DeviceInfoProvider is not registered E: 340 [ZCL]Trying to write invalid Calendar Type E: 345 [ZCL]Failed to write calendar type with error: 0x87 D: 350 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to b6fdcd5e D: 357 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 48327bab I: 363 [ZCL]Cluster OnOff: attribute OnOff set to 0 D: 368 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 5724edba I: 374 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254 D: 380 [IN]UDP::Init bind&listen port=5540 E: 384 [IN]SO_REUSEPORT failed: 109 D: 388 [IN]UDP::Init bound to port=5540 D: 391 [IN]BLEBase::Init - setting/overriding transport D: 396 [IN]TransportMgr initialized D: 406 [DIS]Add fabric pairing table delegate D: 410 [DL]Using Thread extended MAC for hostname. D: 421 [SC]Assigned local session key ID 242 D: 425 [SC]Waiting for PBKDF param request D: 429 [DL]CHIPoBLE advertising set to on I: 433 [DIS]Updating services using commissioning mode 1 D: 438 [DL]Using Thread extended MAC for hostname. D: 443 [DL]Using Thread extended MAC for hostname. I: 448 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 E: 457 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003 D: 464 [DIS]Scheduling discovery timeout in 900s E: 468 [DIS]Failed to finalize service update: Error CHIP:0x0000001C I: 474 [DIS]Updating services using commissioning mode 1 D: 479 [DL]Using Thread extended MAC for hostname. D: 484 [DL]Using Thread extended MAC for hostname. I: 489 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 E: 498 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003 D: 505 [DIS]Scheduling discovery timeout in 900s E: 509 [DIS]Failed to finalize service update: Error CHIP:0x0000001C I: 515 [DIS]Delaying proxy of operational discovery: missing delegate I: 522 [IN]CASE Server enabling CASE session setups I: 526 [SVR]Joining Multicast groups D: 529 [ZCL]Emitting StartUp event D: 533 [EVL]LogEvent event number: 0x0000000000000000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000215 D: 547 [ZCL]GeneralDiagnosticsDelegate: OnDeviceRebooted D: 552 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to 362afc59 D: 559 [EVL]LogEvent event number: 0x0000000000000001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000022E I: 573 [SVR]Server Listening... I: 575 [DL]Device Configuration: I: 579 [DL] Serial Number: TEST_SN I: 582 [DL] Vendor Id: 65521 (0xFFF1) I: 586 [DL] Product Id: 32773 (0x8005) I: 590 [DL] Hardware Version: 0 I: 593 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 599 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 606 [DL] Manufacturing Date: (not set) I: 610 [DL] Device Type: 65535 (0xFFFF) I: 614 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00] I: 619 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 625 [SVR]https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00 I: 634 [SVR]Manual pairing code: [34970112332] I: 639 [DL]CHIP task running I: 645 [DL]CHIPoBLE advertising started I: 649 [DL]NFC Tag emulation started uart:~$ I: 30648 [DL]CHIPoBLE advertising mode changed to slow I: 31903 [DL]BLE connection established (ConnId: 0x00) I: 31908 [DL]Current number of connections: 1/1 I: 31912 [DL]CHIPoBLE advertising stopped I: 31916 [DL]NFC Tag emulation stopped D: 32735 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 32741 [BLE]local and remote recv window sizes = 5 I: 32746 [BLE]selected BTP version 4 I: 32749 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 32833 [DL]ConnId: 0x00, New CCCD value: 0x0001 D: 32838 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6) D: 32844 [IN]BLE EndPoint 0x20009ac8 Connection Complete I: 32849 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) D: 33028 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 33034 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 33040 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:2535842104 on exchange 32338r D: 33050 [EM]Handling via exchange: 32338r, Delegate: 0x20005940 D: 33056 [SC]Received PBKDF param request D: 33059 [SC]Peer assigned session ID 28636 D: 33063 [SC]Found MRP parameters in the message D: 33068 [SC]Including MRP parameters in PBKDF param response I: 33074 [IN]Prepared unauthenticated message 0x2002d878 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 32338r with MessageCounter:4116404075. I: 33089 [IN]Sending unauthenticated msg 0x2002d878 with MessageCounter:4116404075 to 0x0000000000000000 at monotonic time: 0000000000008141 msec D: 33102 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 139) D: 33109 [SC]Sent PBKDF param response D: 33174 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 33272 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 33278 [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:2535842105 on exchange 32338r D: 33288 [EM]Found matching exchange: 32338r, Delegate: 0x20005940 D: 33294 [SC]Received spake2p msg1 I: 35193 [IN]Prepared unauthenticated message 0x2002d808 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 32338r with MessageCounter:4116404076. I: 35208 [IN]Sending unauthenticated msg 0x2002d808 with MessageCounter:4116404076 to 0x0000000000000000 at monotonic time: 0000000000008988 msec D: 35221 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 132) D: 35228 [SC]Sent spake2p msg2 E: 35230 [DL]Long dispatch time: 1958 ms, for event type 16388 D: 35319 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 35368 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 35374 [EM]Received message of type 0x24 with protocolId (0, 0) and MessageCounter:2535842106 on exchange 32338r D: 35384 [EM]Found matching exchange: 32338r, Delegate: 0x20005940 D: 35390 [SC]Received spake2p msg3 D: 35394 [SC]Sending status report. Protocol code 0, exchange 32338 I: 35400 [IN]Prepared unauthenticated message 0x2002d898 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 32338r with MessageCounter:4116404077. I: 35415 [IN]Sending unauthenticated msg 0x2002d898 with MessageCounter:4116404077 to 0x0000000000000000 at monotonic time: 0000000000008A57 msec D: 35428 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 35) D: 35435 [IN]New secure session created for device , LSID:242 PSID:28636! I: 35444 [SVR]Commissioning completed session establishment step I: 35450 [DIS]Updating services using commissioning mode 0 D: 35455 [DL]Using Thread extended MAC for hostname. D: 35460 [DL]Using Thread extended MAC for hostname. I: 35466 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 E: 35475 [DIS]Failed to advertise extended commissionable node: Error CHIP:0x00000003 D: 35482 [DIS]Scheduling extended discovery timeout in 900s E: 35488 [DIS]Failed to finalize service update: Error CHIP:0x0000001C D: 35494 [DL]CHIPoBLE advertising set to off I: 35515 [SVR]Device completed Rendezvous process E: 35519 [DL]Long dispatch time: 151 ms, for event type 16388 D: 35525 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 35530 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 35537 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:7061790 on exchange 32339r D: 35547 [EM]Handling via exchange: 32339r, Delegate: 0x200078bc D: 35553 [IM]Received Read request D: 35558 [DMG]IM RH moving to [GeneratingReports] D: 35563 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 35571 [DMG] Cluster 31, Attribute 3 is dirty D: 35576 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1) D: 35585 [DMG] Cluster 28, Attribute 4 is dirty D: 35590 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) D: 35599 [DMG] Cluster 28, Attribute 2 is dirty D: 35604 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 35614 [DMG] Cluster 30, Attribute 3 is dirty D: 35619 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 35628 [DMG] Cluster 30, Attribute 2 is dirty D: 35633 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 35642 [DMG] Cluster 30, Attribute 1 is dirty D: 35647 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D: 35656 [DMG] Cluster 30, Attribute 0 is dirty D: 35661 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0) D: 35670 [DMG] Cluster 31, Attribute fffc is dirty D: 35675 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1) D: 35684 [DMG] Sending report (payload has 224 bytes)... I: 35691 [IN]Prepared secure message 0x2002da40 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 32339r with MessageCounter:3086491. I: 35705 [IN]Sending encrypted msg 0x2002da40 with MessageCounter:3086491 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000008B79 msec D: 35718 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 35724 [DMG] OnReportConfirm: NumReports = 0 D: 35729 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 35736 [DMG]IM RH moving to [AwaitingDestruction] D: 35741 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 35806 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 35812 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 17) D: 35904 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 35910 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 35916 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7061791 on exchange 32340r D: 35926 [EM]Handling via exchange: 32340r, Delegate: 0x200078bc D: 35932 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 D: 35941 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 6fa44935 D: 35947 [DMG]ICR moving to [ Preparing] D: 35951 [DMG]ICR moving to [AddingComm] D: 35955 [DMG]ICR moving to [AddedComma] D: 35959 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 35966 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32340r with MessageCounter:3086492. I: 35980 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:3086492 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000008C8B msec D: 35992 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71) D: 35998 [DMG]ICR moving to [CommandSen] D: 36002 [DMG]ICR moving to [AwaitingDe] D: 36051 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 36056 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 36063 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7061792 on exchange 32341r D: 36072 [EM]Handling via exchange: 32341r, Delegate: 0x200078bc D: 36079 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 D: 36102 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 6fa44936 D: 36108 [DMG]ICR moving to [ Preparing] D: 36112 [DMG]ICR moving to [AddingComm] D: 36116 [DMG]ICR moving to [AddedComma] D: 36119 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 36127 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32341r with MessageCounter:3086493. I: 36141 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:3086493 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000008D2C msec D: 36154 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71) D: 36160 [DMG]ICR moving to [CommandSen] D: 36164 [DMG]ICR moving to [AwaitingDe] E: 36167 [DL]Long dispatch time: 111 ms, for event type 16388 D: 36246 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 36251 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 36258 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7061793 on exchange 32342r D: 36267 [EM]Handling via exchange: 32342r, Delegate: 0x200078bc D: 36274 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 36281 [ZCL]OpCreds: Certificate Chain request received for PAI D: 36287 [DMG]ICR moving to [ Preparing] D: 36291 [DMG]ICR moving to [AddingComm] D: 36295 [DMG]ICR moving to [AddedComma] D: 36299 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 36308 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32342r with MessageCounter:3086494. I: 36322 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:3086494 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000008DE2 msec D: 36334 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 36341 [DMG]ICR moving to [CommandSen] D: 36345 [DMG]ICR moving to [AwaitingDe] D: 36391 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 36397 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 36489 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 36494 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 48) D: 36587 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 36592 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 36599 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7061794 on exchange 32343r D: 36609 [EM]Handling via exchange: 32343r, Delegate: 0x200078bc D: 36615 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 36622 [ZCL]OpCreds: Certificate Chain request received for DAC D: 36628 [DMG]ICR moving to [ Preparing] D: 36632 [DMG]ICR moving to [AddingComm] D: 36636 [DMG]ICR moving to [AddedComma] D: 36640 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 36649 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32343r with MessageCounter:3086495. I: 36663 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:3086495 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000008F37 msec D: 36676 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 36682 [DMG]ICR moving to [CommandSen] D: 36686 [DMG]ICR moving to [AwaitingDe] D: 36732 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 36738 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 36830 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 36835 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 77) D: 36928 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 36934 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 36940 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7061795 on exchange 32344r D: 36950 [EM]Handling via exchange: 32344r, Delegate: 0x200078bc D: 36957 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 I: 36964 [ZCL]OpCreds: received an AttestationRequest D: 37000 [DMG]ICR moving to [ Preparing] D: 37004 [DMG]ICR moving to [AddingComm] D: 37008 [DMG]ICR moving to [AddedComma] D: 37012 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 37022 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32344r with MessageCounter:3086496. I: 37036 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:3086496 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000090AC msec D: 37049 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 37055 [DMG]ICR moving to [CommandSen] D: 37059 [DMG]ICR moving to [AwaitingDe] E: 37063 [DL]Long dispatch time: 129 ms, for event type 16388 D: 37122 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 37128 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 37220 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 37226 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 237) D: 37329 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 37419 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 37426 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7061796 on exchange 32345r D: 37436 [EM]Handling via exchange: 32345r, Delegate: 0x200078bc D: 37442 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 I: 37450 [ZCL]OpCreds: commissioner has requested a CSR I: 37801 [ZCL]OpCreds: NewCertificateSigningRequest returned 0 D: 37838 [DMG]ICR moving to [ Preparing] D: 37842 [DMG]ICR moving to [AddingComm] D: 37845 [DMG]ICR moving to [AddedComma] D: 37849 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 37858 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32345r with MessageCounter:3086497. I: 37872 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:3086497 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000093F0 msec D: 37884 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 37891 [DMG]ICR moving to [CommandSen] D: 37895 [DMG]ICR moving to [AwaitingDe] E: 37898 [DL]Long dispatch time: 479 ms, for event type 16388 D: 37959 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 37964 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 138) D: 38049 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 38095 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 38184 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 38192 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7061797 on exchange 32346r D: 38202 [EM]Handling via exchange: 32346r, Delegate: 0x200078bc D: 38208 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B I: 38215 [ZCL]OpCreds: commissioner has added a trusted root Cert D: 38221 [DMG]ICR moving to [ Preparing] D: 38225 [DMG]ICR moving to [AddingComm] D: 38229 [DMG]ICR moving to [AddedComma] D: 38232 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 40c40f12 D: 38239 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 38246 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32346r with MessageCounter:3086498. I: 38260 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:3086498 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000009574 msec D: 38273 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 68) D: 38280 [DMG]ICR moving to [CommandSen] D: 38283 [DMG]ICR moving to [AwaitingDe] E: 38287 [DL]Long dispatch time: 103 ms, for event type 16388 D: 38365 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 38370 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 38454 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 38462 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7061798 on exchange 32347r D: 38472 [EM]Handling via exchange: 32347r, Delegate: 0x200078bc D: 38478 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 I: 38486 [ZCL]OpCreds: Received AddNOC command I: 38491 [DIS]Verifying the received credentials I: 38555 [DIS]Added new fabric at index: 0x1, Initialized: 1 I: 38560 [DIS]Assigned compressed fabric ID: 0xC45284823480B187, node ID: 0x000000000000000B I: 38599 [DIS]Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage I: 38606 [ZCL]OpCreds: Fabric index 0x1 was persisted to storage. FabricId 0000000000000001, NodeId 000000000000000B, VendorId 0x34B0 I: 38618 [ZCL]OpCreds: Call to fabricListChanged D: 38622 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 40c40f13 D: 38629 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 40c40f14 D: 38663 [EVL]LogEvent event number: 0x0000000000000002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x0000000000009706 I: 38677 [ZCL]OpCreds: ACL entry created for Fabric 1 CASE Admin NodeId 0x000000000001B669 D: 38685 [DL]Using Thread extended MAC for hostname. I: 38690 [DIS]Advertise operational node C45284823480B187-000000000000000B D: 38696 [DMG]ICR moving to [ Preparing] D: 38700 [DMG]ICR moving to [AddingComm] D: 38704 [DMG]ICR moving to [AddedComma] I: 38707 [ZCL]OpCreds: successfully created fabric index 1 via AddNOC D: 38714 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 38721 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 32347r with MessageCounter:3086499. I: 38735 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:3086499 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000000974F msec D: 38748 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71) D: 38754 [DMG]ICR moving to [CommandSen] D: 38758 [DMG]ICR moving to [AwaitingDe] E: 38761 [DL]Long dispatch time: 307 ms, for event type 16388 D: 38814 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 38820 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 38827 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7061799 on exchange 32348r D: 38836 [EM]Handling via exchange: 32348r, Delegate: 0x200078bc D: 38843 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003 D: 38863 [DMG]ICR moving to [ Preparing] D: 38867 [DMG]ICR moving to [AddingComm] D: 38870 [DMG]ICR moving to [AddedComma] D: 38874 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 38882 [IN]Prepared secure message 0x2002d908 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 32348r with MessageCounter:3086500. I: 38896 [IN]Sending encrypted msg 0x2002d908 with MessageCounter:3086500 to 0xFFFFFFFB00000000 (1) at monotonic time: 00000000000097EF msec D: 38908 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71) D: 38915 [DMG]ICR moving to [CommandSen] D: 38919 [DMG]ICR moving to [AwaitingDe] E: 38922 [DL]Long dispatch time: 102 ms, for event type 16388 D: 38994 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 39000 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 39006 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7061800 on exchange 32349r D: 39016 [EM]Handling via exchange: 32349r, Delegate: 0x200078bc D: 39022 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006 D: 39050 [DMG]Decreasing reference count for CommandHandler, remaining 1 D: 39056 [DL]OpenThread State Changed (Flags: 0x1006c100) D: 39061 [DL] Network Name: OpenThread D: 39065 [DL] PAN Id: 0x1234 D: 39068 [DL] Extended PAN Id: 0x1111111122222222 D: 39072 [DL] Channel: 15 D: 39075 [DL] Mesh Prefix: fdde:ad00:beef::/64 D: 39080 [DL]OpenThread State Changed (Flags: 0x1100101d) D: 39086 [DL] Device Role: DETACHED D: 39089 [DL] Thread Unicast Addresses: D: 39093 [DL] fdde:ad00:beef:0:eba3:f3f6:9d88:565d/64 valid D: 39099 [DL] fe80::c881:8334:8ad4:9cc/64 valid preferred D: 41506 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 41559 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 44034 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 46541 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 46599 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 49074 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 51580 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 51639 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 54114 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 56620 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 56678 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 59199 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 61704 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 61763 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 64239 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 66744 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 66803 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 69278 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 71784 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 71843 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 74363 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 76869 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 76931 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 79403 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 81909 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 81968 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 84443 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 86949 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 87008 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 89528 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 92035 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 92093 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 94568 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) E: 95941 [SVR]Failsafe timer expired E: 95944 [SVR]Commissioning failed (attempt 1): Error CHIP:0x00000032 D: 95950 [IN]Clearing BLE pending packets. I: 95954 [BLE]Releasing end point's BLE connection back to application. I: 95961 [DL]Closing BLE GATT connection (ConnId 00) D: 95969 [SC]Assigned local session key ID 243 D: 95973 [SC]Waiting for PBKDF param request D: 95977 [DL]CHIPoBLE advertising set to on I: 95981 [DIS]Updating services using commissioning mode 1 D: 95986 [DL]Using Thread extended MAC for hostname. D: 95991 [DL]Using Thread extended MAC for hostname. I: 95996 [DIS]Advertise operational node C45284823480B187-000000000000000B E: 96002 [DIS]Failed to advertise operational node: Error CHIP:0x00000003 D: 96009 [DL]Using Thread extended MAC for hostname. I: 96015 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 E: 96026 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003 E: 96033 [DIS]Failed to finalize service update: Error CHIP:0x0000001C I: 96040 [ZCL]OpCreds: Call to FailSafeCleanup D: 96044 [IN]Expiring all connections for fabric 1!! I: 96167 [DIS]Fabric (0x1) deleted. Calling OnFabricDeletedFromStorage I: 96262 [ZCL]OpCreds: Fabric index 0x1 was deleted from fabric storage. I: 96269 [ZCL]OpCreds: Call to fabricListChanged D: 96273 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 40c40f15 D: 96280 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 40c40f16 D: 96287 [EVL]LogEvent event number: 0x0000000000000003 priority: 1, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000001781E D: 96301 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet I: 96334 [DIS]Updating services using commissioning mode 1 D: 96339 [DL]Using Thread extended MAC for hostname. D: 96345 [DL]Using Thread extended MAC for hostname. I: 96350 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 E: 96359 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003 D: 96366 [DIS]Scheduling discovery timeout in 900s E: 96370 [DIS]Failed to finalize service update: Error CHIP:0x0000001C D: 96377 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 6fa44937 D: 96383 [ZCL]Failsafe timeout, tell platform driver to revert network credentials. D: 96444 [DMG]Decreasing reference count for CommandHandler, remaining 0 E: 96451 [DMG]Failed to send command response: 3 D: 96455 [DMG]ICR moving to [AwaitingDe] E: 96459 [DL]Long dispatch time: 518 ms, for event type 32785 D: 96468 [DL]OpenThread State Changed (Flags: 0x11002006) D: 96473 [DL] Device Role: DISABLED D: 96476 [DL] Thread Unicast Addresses: D: 96481 [DL]OpenThread State Changed (Flags: 0x10000000) I: 96488 [DL]BLE GAP connection terminated (reason 0x16) I: 96493 [DL]Current number of connections: 0/1 I: 96499 [DL]CHIPoBLE advertising started I: 96504 [DL]NFC Tag emulation started