I: 30687 [DL]CHIPoBLE advertising mode changed to slow I: nRF5 802154 radio initialized I: 4 Sectors of 4096 bytes I: alloc wra: 1, af8 I: data wra: 1, 314 ooting Zephyr OS build v3.2.99-ncs1 *** [1;I: Init CHIP stack 32muart:~$ : 226 [DL]BLE address: FD:56:38:BE:8B:8D 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: 252 [DL]OpenThread started: OK I: 255 [DL]Setting OpenThread device type to ROUTER I: 260 [SVR]Server initializing... D: 263 [FP]Initializing FabricTable from persistent storage I: 269 [TS]Last Known Good Time: 2023-01-25T11:24:03 I: 275 [DMG]AccessControl: initializing I: 278 [DMG]Examples::AccessControlDelegate::Init I: 283 [DMG]AccessControl: setting I: 286 [DMG]DefaultAclStorage: initializing I: 290 [DMG]DefaultAclStorage: 0 entries loaded D: 294 [IN]UDP::Init bind&listen port=5540 E: 298 [IN]SO_REUSEPORT failed: 109 D: 302 [IN]UDP::Init bound to port=5540 D: 305 [IN]BLEBase::Init - setting/overriding transport D: 310 [IN]TransportMgr initialized D: 318 [DL]Using Thread extended MAC for hostname. I: 325 [ZCL]Using ZAP configuration... D: 329 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0 D: 338 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0 D: 346 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0 I: 353 [DMG]AccessControlCluster: initializing D: 357 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fc583588 D: 364 [DL]Boot reason: 1 D: 366 [ZCL]GeneralDiagnostics: OnDeviceReboot D: 370 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to e18e98d9 D: 377 [EVL]LogEvent event number: 0x0000000000010000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000178 I: 390 [ZCL]Initiating Admin Commissioning cluster. D: 395 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to a8d0ac13 D: 402 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to c8665ae5 D: 408 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to c8665ae6 I: 414 [ZCL]On/Off set value: 1 0 I: 417 [ZCL]On/off already set to new value D: 422 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to fe5bebbf I: 428 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254 D: 434 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level D: 444 [IN]SecureSession[0x20003650]: Allocated Type:1 LSID:38145 D: 450 [SC]Assigned local session key ID 38145 D: 454 [SC]Waiting for PBKDF param request D: 458 [DL]CHIPoBLE advertising set to on I: 462 [DIS]Updating services using commissioning mode 1 D: 467 [DL]Using Thread extended MAC for hostname. D: 472 [DL]Using Thread extended MAC for hostname. I: 477 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 E: 486 [DIS]Failed to advertise commissionable node: 3 E: 491 [DIS]Failed to finalize service update: 1c I: 495 [DIS]Updating services using commissioning mode 1 D: 500 [DL]Using Thread extended MAC for hostname. D: 505 [DL]Using Thread extended MAC for hostname. I: 511 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 E: 520 [DIS]Failed to advertise commissionable node: 3 E: 525 [DIS]Failed to finalize service update: 1c I: 529 [DIS]Delaying proxy of operational discovery: missing delegate I: 535 [IN]CASE Server enabling CASE session setups D: 540 [IN]SecureSession[0x20003708]: Allocated Type:2 LSID:38146 D: 546 [SC]Allocated SecureSession (0x20003708) - waiting for Sigma1 msg I: 552 [SVR]Joining Multicast groups D: 556 [ZCL]Emitting StartUp event D: 559 [EVL]LogEvent event number: 0x0000000000010001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x000000000000022F I: 573 [SVR]Server Listening... I: 576 [DL]Device Configuration: I: 579 [DL] Serial Number: 11223344556677889900 I: 584 [DL] Vendor Id: 65521 (0xFFF1) I: 587 [DL] Product Id: 32773 (0x8005) I: 591 [DL] Hardware Version: 0 I: 595 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 601 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 608 [DL] Manufacturing Date: (not set) I: 612 [DL] Device Type: 65535 (0xFFFF) I: 617 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00] I: 621 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 628 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00 I: 636 [SVR]Manual pairing code: [34970112332] I: 642 [DL]CHIP task running I: 646 [DL]CHIPoBLE advertising started D: 651 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 6530eb55 I: 657 [ZCL]Cluster OnOff: attribute OnOff set to 0 D: 662 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to fe5bebc0 I: 668 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254 D: 674 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level I: 683 [DL]NFC Tag emulation started I: 30650 [DL]CHIPoBLE advertising mode changed to slow I: 37021 [DL]BLE connection established (ConnId: 0x00) I: 37026 [DL]Current number of connections: 1/2 I: 37030 [DL]CHIPoBLE advertising stopped I: 37034 [DL]NFC Tag emulation stopped D: 37609 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 37616 [BLE]local and remote recv window sizes = 5 I: 37621 [BLE]selected BTP version 4 I: 37624 [BLE]using BTP fragment sizes rx 128 / tx 128. D: 37707 [DL]ConnId: 0x00, New CCCD value: 0x0002 D: 37711 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) D: 37718 [IN]BLE EndPoint 0x20012270 Connection Complete I: 37724 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131) D: 37804 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 37853 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 37860 [EM]>>> [E:49049r M:138475096] (U) Msg RX from 0:A572A95ADE084B6B [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) D: 37872 [EM]Handling via exchange: 49049r, Delegate: 0x20005834 D: 37878 [SC]Received PBKDF param request D: 37881 [SC]Peer assigned session ID 19992 D: 37885 [SC]Found MRP parameters in the message D: 37890 [SC]Including MRP parameters in PBKDF param response I: 37896 [EM]<<< [E:49049r M:182311160] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 37908 [IN](U) Sending msg 182311160 to IP address 'BLE' D: 37913 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 37921 [SC]Sent PBKDF param response D: 37999 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 38007 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 14) D: 38145 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 38153 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 38161 [EM]>>> [E:49049r M:138475097] (U) Msg RX from 0:A572A95ADE084B6B [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) D: 38172 [EM]Found matching exchange: 49049r, Delegate: 0x20005834 D: 38178 [SC]Received spake2p msg1 I: 40106 [EM]<<< [E:49049r M:182311161] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 40117 [IN](U) Sending msg 182311161 to IP address 'BLE' D: 40122 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 40129 [SC]Sent spake2p msg2 E: 40132 [DL]Long dispatch time: 1979 ms, for event type 16388 D: 40193 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40200 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) D: 40291 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40298 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 40306 [EM]>>> [E:49049r M:138475098] (U) Msg RX from 0:A572A95ADE084B6B [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) D: 40317 [EM]Found matching exchange: 49049r, Delegate: 0x20005834 D: 40323 [SC]Received spake2p msg3 D: 40326 [SC]Sending status report. Protocol code 0, exchange 49049 I: 40333 [EM]<<< [E:49049r M:182311162] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 40344 [IN](U) Sending msg 182311162 to IP address 'BLE' D: 40349 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35) I: 40358 [SC]SecureSession[0x20003650]: Moving from state 'kEstablishing' --> 'kActive' D: 40366 [IN]SecureSession[0x20003650]: Activated - Type:1 LSID:38145 D: 40372 [IN]New secure session activated for device , LSID:38145 PSID:19992! I: 40380 [SVR]Commissioning completed session establishment step I: 40387 [DIS]Updating services using commissioning mode 0 D: 40392 [DL]Using Thread extended MAC for hostname. D: 40397 [DL]Using Thread extended MAC for hostname. I: 40403 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 E: 40412 [DIS]Failed to advertise extended commissionable node: 3 D: 40418 [DIS]Scheduling extended discovery timeout in 900s E: 40423 [DIS]Failed to finalize service update: 1c D: 40428 [DL]CHIPoBLE advertising set to off I: 40432 [SVR]Device completed Rendezvous process E: 40437 [DL]Long dispatch time: 139 ms, for event type 16388 D: 40443 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40451 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 40459 [EM]>>> [E:49050r M:103199849] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 40469 [EM]Handling via exchange: 49050r, Delegate: 0x2000fc3c D: 40474 [IM]Received Read request D: 40478 [DMG]IM RH moving to [GeneratingReports] D: 40483 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 40492 [DMG] Cluster 28, Attribute 2 is dirty D: 40497 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 40506 [DMG] Sending report (payload has 37 bytes)... I: 40512 [EM]<<< [E:49050r M:80103682] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 40522 [IN](S) Sending msg 80103682 on secure session with LSID: 38145 D: 40528 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72) D: 40536 [DMG] OnReportConfirm: NumReports = 0 D: 40540 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 40548 [DMG]IM RH moving to [AwaitingDestruction] D: 40552 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 40632 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40640 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 40648 [EM]>>> [E:49051r M:103199850] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 40658 [EM]Handling via exchange: 49051r, Delegate: 0x2000fc3c D: 40664 [IM]Received Read request D: 40667 [DMG]IM RH moving to [GeneratingReports] D: 40672 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 40681 [DMG] Cluster 28, Attribute 4 is dirty D: 40686 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) D: 40695 [DMG] Sending report (payload has 37 bytes)... I: 40701 [EM]<<< [E:49051r M:80103683] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 40711 [IN](S) Sending msg 80103683 on secure session with LSID: 38145 D: 40717 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72) D: 40725 [DMG] OnReportConfirm: NumReports = 0 D: 40730 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 40737 [DMG]IM RH moving to [AwaitingDestruction] D: 40741 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 40778 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40786 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 40794 [EM]>>> [E:49052r M:103199851] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 40804 [EM]Handling via exchange: 49052r, Delegate: 0x2000fc3c D: 40810 [IM]Received Read request D: 40814 [DMG]IM RH moving to [GeneratingReports] D: 40818 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 40827 [DMG] Cluster 3e, Attribute 2 is dirty D: 40832 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 40841 [DMG] Sending report (payload has 36 bytes)... I: 40847 [EM]<<< [E:49052r M:80103684] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 40857 [IN](S) Sending msg 80103684 on secure session with LSID: 38145 D: 40863 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 40871 [DMG] OnReportConfirm: NumReports = 0 D: 40876 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 40883 [DMG]IM RH moving to [AwaitingDestruction] D: 40888 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 40924 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40932 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 40940 [EM]>>> [E:49053r M:103199852] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 40950 [EM]Handling via exchange: 49053r, Delegate: 0x2000fc3c D: 40956 [IM]Received Read request D: 40960 [DMG]IM RH moving to [GeneratingReports] D: 40965 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 40973 [DMG] Cluster 3e, Attribute 3 is dirty D: 40978 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 40987 [DMG] Sending report (payload has 36 bytes)... I: 40993 [EM]<<< [E:49053r M:80103685] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 41003 [IN](S) Sending msg 80103685 on secure session with LSID: 38145 D: 41010 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 41017 [DMG] OnReportConfirm: NumReports = 0 D: 41022 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 41029 [DMG]IM RH moving to [AwaitingDestruction] D: 41034 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 41071 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41078 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 41086 [EM]>>> [E:49054r M:103199853] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 41097 [EM]Handling via exchange: 49054r, Delegate: 0x2000fc3c D: 41102 [IM]Received Read request D: 41106 [DMG]IM RH moving to [GeneratingReports] D: 41111 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 41119 [DMG] Cluster 3e, Attribute 1 is dirty D: 41124 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D: 41133 [DMG] Sending report (payload has 36 bytes)... I: 41139 [EM]<<< [E:49054r M:80103686] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 41149 [IN](S) Sending msg 80103686 on secure session with LSID: 38145 D: 41156 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 41163 [DMG] OnReportConfirm: NumReports = 0 D: 41168 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 41176 [DMG]IM RH moving to [AwaitingDestruction] D: 41180 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 41217 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41225 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 41233 [EM]>>> [E:49055r M:103199854] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 41243 [EM]Handling via exchange: 49055r, Delegate: 0x2000fc3c D: 41248 [IM]Received Read request D: 41252 [DMG]IM RH moving to [GeneratingReports] D: 41257 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 41266 [DMG] Cluster 1d, Attribute 1 is dirty D: 41271 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D: 41280 [DMG] Sending report (payload has 400 bytes)... I: 41288 [EM]<<< [E:49055r M:80103687] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 41298 [IN](S) Sending msg 80103687 on secure session with LSID: 38145 D: 41304 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41312 [DMG] OnReportConfirm: NumReports = 0 D: 41317 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 41324 [DMG]IM RH moving to [AwaitingDestruction] D: 41329 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 41363 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41370 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41460 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41468 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41558 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41565 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57) D: 41656 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41663 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 41753 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 41761 [EM]>>> [E:49056r M:103199855] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 41771 [EM]Handling via exchange: 49056r, Delegate: 0x2000fc3c D: 41777 [IM]Received Read request D: 41781 [DMG]IM RH moving to [GeneratingReports] D: 41785 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 41794 [DMG] Cluster 31, Attribute fffc is dirty D: 41799 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0) D: 41808 [DMG] Sending report (payload has 37 bytes)... I: 41814 [EM]<<< [E:49056r M:80103688] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 41824 [IN](S) Sending msg 80103688 on secure session with LSID: 38145 D: 41831 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72) D: 41838 [DMG] OnReportConfirm: NumReports = 0 D: 41843 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 41851 [DMG]IM RH moving to [AwaitingDestruction] D: 41855 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 41899 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 42897 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 42904 [EM]>>> [E:49057r M:103199856] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) D: 42915 [EM]Handling via exchange: 49057r, Delegate: 0x2000fc3c D: 42921 [DMG]Got Timed Request with timeout 10000: handler 0x20010038 exchange 49057r I: 42929 [EM]<<< [E:49057r M:80103689] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 42939 [IN](S) Sending msg 80103689 on secure session with LSID: 38145 D: 42946 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43) D: 42954 [DMG]Timed Request time limit 0x000000000000CED9: handler 0x20010038 exchange 49057r D: 43032 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 43040 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 43048 [EM]>>> [E:49057r M:103199857] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 43059 [EM]Found matching exchange: 49057r, Delegate: 0x20010038 D: 43065 [DMG]Timed following action arrived at 0x000000000000A839: handler 0x20010038 exchange 49057r D: 43074 [DMG]Handing timed invoke to IM engine: handler 0x20010038 exchange 49057r D: 43082 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 I: 43090 [FS]GeneralCommissioning: Received ArmFailSafe (120s) D: 43095 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fc583589 D: 43102 [DMG]Command handler moving to [ Preparing] D: 43106 [DMG]Command handler moving to [AddingComm] D: 43111 [DMG]Command handler moving to [AddedComma] D: 43116 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 43124 [EM]<<< [E:49057r M:80103690] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 43134 [IN](S) Sending msg 80103690 on secure session with LSID: 38145 D: 43141 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 43149 [DMG]Command handler moving to [CommandSen] D: 43153 [DMG]Command handler moving to [AwaitingDe] E: 43158 [DL]Long dispatch time: 118 ms, for event type 16388 D: 43212 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 43220 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 43228 [EM]>>> [E:49058r M:103199858] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 43238 [EM]Handling via exchange: 49058r, Delegate: 0x2000fc3c D: 43244 [IM]Received Read request D: 43247 [DMG]IM RH moving to [GeneratingReports] D: 43252 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 43261 [DMG] Cluster 30, Attribute 3 is dirty D: 43266 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 43275 [DMG] Sending report (payload has 36 bytes)... I: 43281 [EM]<<< [E:49058r M:80103691] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 43291 [IN](S) Sending msg 80103691 on secure session with LSID: 38145 D: 43297 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 43305 [DMG] OnReportConfirm: NumReports = 0 D: 43310 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 43317 [DMG]IM RH moving to [AwaitingDestruction] D: 43322 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 43392 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 43400 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 43408 [EM]>>> [E:49059r M:103199859] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) D: 43418 [EM]Handling via exchange: 49059r, Delegate: 0x2000fc3c D: 43424 [DMG]Got Timed Request with timeout 10000: handler 0x20010038 exchange 49059r I: 43432 [EM]<<< [E:49059r M:80103692] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 43443 [IN](S) Sending msg 80103692 on secure session with LSID: 38145 D: 43449 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43) D: 43457 [DMG]Timed Request time limit 0x000000000000D0D1: handler 0x20010038 exchange 49059r D: 43527 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 43535 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 43543 [EM]>>> [E:49059r M:103199860] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 43554 [EM]Found matching exchange: 49059r, Delegate: 0x20010038 D: 43560 [DMG]Timed following action arrived at 0x000000000000AA28: handler 0x20010038 exchange 49059r D: 43569 [DMG]Handing timed invoke to IM engine: handler 0x20010038 exchange 49059r D: 43577 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 D: 43593 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fc58358a D: 43599 [DMG]Command handler moving to [ Preparing] D: 43604 [DMG]Command handler moving to [AddingComm] D: 43609 [DMG]Command handler moving to [AddedComma] D: 43613 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 43621 [EM]<<< [E:49059r M:80103693] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 43632 [IN](S) Sending msg 80103693 on secure session with LSID: 38145 D: 43638 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 43646 [DMG]Command handler moving to [CommandSen] D: 43651 [DMG]Command handler moving to [AwaitingDe] E: 43655 [DL]Long dispatch time: 120 ms, for event type 16388 D: 43707 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 43715 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 43723 [EM]>>> [E:49060r M:103199861] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 43734 [EM]Handling via exchange: 49060r, Delegate: 0x2000fc3c D: 43740 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 43747 [ZCL]OpCreds: Certificate Chain request received for DAC D: 43754 [DMG]Command handler moving to [ Preparing] D: 43758 [DMG]Command handler moving to [AddingComm] D: 43763 [DMG]Command handler moving to [AddedComma] D: 43768 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 43777 [EM]<<< [E:49060r M:80103694] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 43788 [IN](S) Sending msg 80103694 on secure session with LSID: 38145 D: 43794 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 43803 [DMG]Command handler moving to [CommandSen] D: 43807 [DMG]Command handler moving to [AwaitingDe] D: 43886 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 43894 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 43976 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 43984 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 44066 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 44074 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 44157 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 44165 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 44172 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57) D: 44248 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 44255 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 44263 [EM]>>> [E:49061r M:103199862] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 44274 [EM]Handling via exchange: 49061r, Delegate: 0x2000fc3c D: 44281 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 44288 [ZCL]OpCreds: Certificate Chain request received for PAI D: 44294 [DMG]Command handler moving to [ Preparing] D: 44299 [DMG]Command handler moving to [AddingComm] D: 44304 [DMG]Command handler moving to [AddedComma] D: 44309 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 44318 [EM]<<< [E:49061r M:80103695] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 44329 [IN](S) Sending msg 80103695 on secure session with LSID: 38145 D: 44335 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 44343 [DMG]Command handler moving to [CommandSen] D: 44348 [DMG]Command handler moving to [AwaitingDe] D: 44426 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 44434 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 44516 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 44524 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 44606 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 44614 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 44697 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 44705 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 44712 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 28) D: 44786 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 44795 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 44803 [EM]>>> [E:49062r M:103199863] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 44814 [EM]Handling via exchange: 49062r, Delegate: 0x2000fc3c D: 44820 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 I: 44828 [ZCL]OpCreds: Received an AttestationRequest command I: 44864 [ZCL]OpCreds: AttestationRequest successful. D: 44869 [DMG]Command handler moving to [ Preparing] D: 44873 [DMG]Command handler moving to [AddingComm] D: 44879 [DMG]Command handler moving to [AddedComma] D: 44883 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 44893 [EM]<<< [E:49062r M:80103696] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 44904 [IN](S) Sending msg 80103696 on secure session with LSID: 38145 D: 44911 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 44918 [DMG]Command handler moving to [CommandSen] D: 44923 [DMG]Command handler moving to [AwaitingDe] E: 44928 [DL]Long dispatch time: 133 ms, for event type 16388 D: 44966 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 44974 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 45056 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45064 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 45146 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45154 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 45237 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45245 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 45252 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 45326 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45334 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 90) D: 45416 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45425 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 45433 [EM]>>> [E:49063r M:103199864] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 45444 [EM]Handling via exchange: 49063r, Delegate: 0x2000fc3c D: 45450 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 I: 45458 [ZCL]OpCreds: Received a CSRRequest command D: 45463 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0 I: 45657 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 45693 [ZCL]OpCreds: CSRRequest successful. D: 45697 [DMG]Command handler moving to [ Preparing] D: 45702 [DMG]Command handler moving to [AddingComm] D: 45707 [DMG]Command handler moving to [AddedComma] D: 45712 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 45720 [EM]<<< [E:49063r M:80103697] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 45731 [IN](S) Sending msg 80103697 on secure session with LSID: 38145 D: 45738 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 45745 [DMG]Command handler moving to [CommandSen] D: 45750 [DMG]Command handler moving to [AwaitingDe] E: 45755 [DL]Long dispatch time: 330 ms, for event type 16388 D: 45821 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45829 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 45911 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45919 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 46001 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) I: 47666 [DL]BLE GAP connection terminated (reason 0x13) D: 47672 [IN]Clearing BLE pending packets. I: 47676 [DL]Current number of connections: 0/2 I: 163095 [FS]Fail-safe timer expired E: 163098 [SVR]Failsafe timer expired D: 163102 [IN]SecureSession[0x20003650]: MarkForEviction Type:1 LSID:38145 I: 163108 [SC]SecureSession[0x20003650]: Moving from state 'kActive' --> 'kPendingEviction' D: 163117 [IN]SecureSession[0x20003650]: Released - Type:1 LSID:38145 E: 163123 [SVR]Commissioning failed (attempt 1): 32 D: 163130 [IN]SecureSession[0x20003650]: Allocated Type:1 LSID:38147 D: 163136 [SC]Assigned local session key ID 38147 D: 163140 [SC]Waiting for PBKDF param request D: 163144 [DL]CHIPoBLE advertising set to on I: 163148 [DIS]Updating services using commissioning mode 1 D: 163154 [DL]Using Thread extended MAC for hostname. D: 163159 [DL]Using Thread extended MAC for hostname. I: 163164 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 E: 163174 [DIS]Failed to advertise commissionable node: 3 E: 163179 [DIS]Failed to finalize service update: 1c E: 163184 [ZCL]OpCreds: Got FailSafeTimerExpired E: 163188 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! I: 163195 [TS]Pending Last Known Good Time: 2023-01-25T11:24:03 I: 163201 [TS]Previous Last Known Good Time: 2023-01-25T11:24:03 I: 163207 [TS]Reverted Last Known Good Time to previous value D: 163212 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fc58358b D: 163219 [ZCL]Failsafe timeout, tell platform driver to revert network credentials. E: 163227 [DL]Long dispatch time: 129 ms, for event type 32782 I: 163233 [FS]Fail-safe cleanly disarmed I: 163238 [DL]CHIPoBLE advertising started I: 163244 [DL]NFC Tag emulation started I: 193243 [DL]CHIPoBLE advertising mode changed to slow