uart:~$ I: nRF5 802154 radio initialized I: 4 Sectors of 4096 bytes I: alloc wra: 0, f58 I: data wra: 0, 90 *** Booting Zephyr OS build v3.2.99-ncs1 *** I: Init CHIP stack I: 165 [DL]BLE address: FE:D1:B6:82:93:A6 I: 186 [DL]OpenThread SED interval set to 1000ms I: 191 [DL]OpenThread started: OK I: 194 [DL]Setting OpenThread device type to SLEEPY END DEVICE I: 200 [SVR]Server initializing... D: 203 [FP]Initializing FabricTable from persistent storage I: 209 [TS]Last Known Good Time: 2023-02-09T11:08:43 I: 214 [DMG]AccessControl: initializing I: 217 [DMG]Examples::AccessControlDelegate::Init I: 222 [DMG]AccessControl: setting I: 225 [DMG]DefaultAclStorage: initializing I: 229 [DMG]DefaultAclStorage: 0 entries loaded D: 233 [IN]UDP::Init bind&listen port=5540 E: 237 [IN]SO_REUSEPORT failed: 109 D: 240 [IN]UDP::Init bound to port=5540 D: 244 [IN]BLEBase::Init - setting/overriding transport D: 249 [IN]TransportMgr initialized D: 253 [DL]Using Thread extended MAC for hostname. I: 259 [ZCL]Using ZAP configuration... D: 263 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0 I: 270 [DMG]AccessControlCluster: initializing D: 274 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 76c00f3d D: 281 [DL]Boot reason: 1 D: 283 [ZCL]GeneralDiagnostics: OnDeviceReboot D: 287 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to a4722add D: 294 [EVL]LogEvent event number: 0x0000000000010000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000125 I: 307 [ZCL]Initiating Admin Commissioning cluster. I: 312 [ZCL]Door Lock server initialized D: 315 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to e778dc20 I: 322 [ZCL]Door Lock cluster initialized at endpoint #1 D: 327 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc483 D: 333 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc484 D: 339 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc485 D: 345 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc486 D: 352 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc487 D: 358 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc488 D: 364 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc489 D: 371 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc48a I: 377 [DIS]Updating services using commissioning mode 0 D: 382 [DL]Using Thread extended MAC for hostname. D: 387 [DL]Using Thread extended MAC for hostname. I: 391 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0 E: 400 [DIS]Failed to advertise extended commissionable node: 3 D: 406 [DIS]Scheduling extended discovery timeout in 900s E: 411 [DIS]Failed to finalize service update: 1c I: 415 [DIS]Delaying proxy of operational discovery: missing delegate I: 422 [IN]CASE Server enabling CASE session setups D: 427 [IN]SecureSession[0x20004850]: Allocated Type:2 LSID:22668 D: 432 [SC]Allocated SecureSession (0x20004850) - waiting for Sigma1 msg I: 439 [SVR]Joining Multicast groups D: 442 [ZCL]Emitting StartUp event D: 445 [EVL]LogEvent event number: 0x0000000000010001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x00000000000001BD I: 459 [SVR]Server Listening... I: 462 [DL]Device Configuration: I: 465 [DL] Serial Number: 11223344556677889900 I: 469 [DL] Vendor Id: 65521 (0xFFF1) I: 473 [DL] Product Id: 32774 (0x8006) I: 476 [DL] Hardware Version: 0 I: 479 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 485 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 491 [DL] Manufacturing Date: (not set) I: 495 [DL] Device Type: 65535 (0xFFFF) I: 499 [SVR]SetupQRCode: [MT:8IXS142C00KA0648G00] I: 503 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 510 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A8IXS142C00KA0648G00 I: 518 [SVR]Manual pairing code: [34970112332] I: 524 [DL]CHIP task running I: 526 [DIS]Updating services using commissioning mode 0 D: 531 [DL]Using Thread extended MAC for hostname. D: 536 [DL]Using Thread extended MAC for hostname. I: 541 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0 E: 550 [DIS]Failed to advertise extended commissionable node: 3 E: 555 [DIS]Failed to finalize service update: 1c D: 560 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc48b D: 42231 [IN]SecureSession[0x20004908]: Allocated Type:1 LSID:22669 D: 42237 [SC]Assigned local session key ID 22669 D: 42241 [SC]Waiting for PBKDF param request D: 42245 [DL]CHIPoBLE advertising set to on I: 42249 [DIS]Updating services using commissioning mode 1 D: 42255 [DL]Using Thread extended MAC for hostname. D: 42260 [DL]Using Thread extended MAC for hostname. I: 42265 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1 E: 42274 [DIS]Failed to advertise commissionable node: 3 E: 42279 [DIS]Failed to finalize service update: 1c I: 42287 [DL]CHIPoBLE advertising started I: 42291 [DL]NFC Tag emulation started I: 42481 [DL]BLE connection established (ConnId: 0x00) I: 42486 [DL]Current number of connections: 1/2 I: 42491 [DL]CHIPoBLE advertising stopped I: 42495 [DL]NFC Tag emulation stopped D: 43017 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 43024 [BLE]local and remote recv window sizes = 5 I: 43029 [BLE]selected BTP version 4 I: 43032 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 43107 [DL]ConnId: 0x00, New CCCD value: 0x0002 D: 43111 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) D: 43119 [IN]BLE EndPoint 0x20010a28 Connection Complete I: 43124 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) D: 43167 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 43175 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 43183 [EM]>>> [E:24236r M:26347726] (U) Msg RX from 0:6C6441EF3331B32B [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) D: 43194 [EM]Handling via exchange: 24236r, Delegate: 0x20006a34 D: 43200 [SC]Received PBKDF param request D: 43204 [SC]Peer assigned session ID 53812 D: 43208 [SC]Found MRP parameters in the message D: 43212 [SC]Including MRP parameters in PBKDF param response I: 43218 [EM]<<< [E:24236r M:246000293] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 43230 [IN](U) Sending msg 246000293 to IP address 'BLE' D: 43235 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140) D: 43243 [SC]Sent PBKDF param response D: 43347 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 43379 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 43386 [EM]>>> [E:24236r M:26347727] (U) Msg RX from 0:6C6441EF3331B32B [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) D: 43397 [EM]Found matching exchange: 24236r, Delegate: 0x20006a34 D: 43403 [SC]Received spake2p msg1 I: 44949 [EM]<<< [E:24236r M:246000294] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 44960 [IN](U) Sending msg 246000294 to IP address 'BLE' D: 44965 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132) D: 44973 [SC]Sent spake2p msg2 E: 44975 [DL]Long dispatch time: 1597 ms, for event type 16388 D: 45087 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45095 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 45103 [EM]>>> [E:24236r M:26347728] (U) Msg RX from 0:6C6441EF3331B32B [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) D: 45114 [EM]Found matching exchange: 24236r, Delegate: 0x20006a34 D: 45120 [SC]Received spake2p msg3 D: 45123 [SC]Sending status report. Protocol code 0, exchange 24236 I: 45129 [EM]<<< [E:24236r M:246000295] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 45140 [IN](U) Sending msg 246000295 to IP address 'BLE' D: 45145 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35) I: 45154 [SC]SecureSession[0x20004908]: Moving from state 'kEstablishing' --> 'kActive' D: 45162 [IN]SecureSession[0x20004908]: Activated - Type:1 LSID:22669 D: 45168 [IN]New secure session activated for device , LSID:22669 PSID:53812! I: 45177 [SVR]Commissioning completed session establishment step I: 45183 [DIS]Updating services using commissioning mode 0 D: 45188 [DL]Using Thread extended MAC for hostname. D: 45193 [DL]Using Thread extended MAC for hostname. I: 45198 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0 E: 45208 [DIS]Failed to advertise extended commissionable node: 3 D: 45214 [DIS]Scheduling extended discovery timeout in 900s E: 45219 [DIS]Failed to finalize service update: 1c D: 45224 [DL]CHIPoBLE advertising set to off I: 45228 [SVR]Device completed Rendezvous process E: 45232 [DL]Long dispatch time: 137 ms, for event type 16388 D: 45238 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45245 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 45253 [EM]>>> [E:24237r M:42699344] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 45263 [EM]Handling via exchange: 24237r, Delegate: 0x2000e3f4 D: 45269 [IM]Received Read request D: 45273 [DMG]IM RH moving to [GeneratingReports] D: 45278 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 45286 [DMG] Cluster 28, Attribute 4 is dirty D: 45291 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) D: 45300 [DMG] Cluster 28, Attribute 2 is dirty D: 45305 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 45314 [DMG] Sending report (payload has 64 bytes)... I: 45320 [EM]<<< [E:24237r M:131709115] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 45330 [IN](S) Sending msg 131709115 on secure session with LSID: 22669 D: 45337 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 99) D: 45344 [DMG] OnReportConfirm: NumReports = 0 D: 45349 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 45356 [DMG]IM RH moving to [AwaitingDestruction] D: 45361 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 45417 [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:24238r M:42699345] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 45443 [EM]Handling via exchange: 24238r, Delegate: 0x2000e3f4 D: 45449 [IM]Received Read request D: 45453 [DMG]IM RH moving to [GeneratingReports] D: 45457 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 45466 [DMG] Cluster 3e, Attribute 2 is dirty D: 45471 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 45480 [DMG] Sending report (payload has 36 bytes)... I: 45486 [EM]<<< [E:24238r M:131709116] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 45496 [IN](S) Sending msg 131709116 on secure session with LSID: 22669 D: 45502 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 45510 [DMG] OnReportConfirm: NumReports = 0 D: 45514 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 45521 [DMG]IM RH moving to [AwaitingDestruction] D: 45526 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 45567 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45575 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 45583 [EM]>>> [E:24239r M:42699346] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 45593 [EM]Handling via exchange: 24239r, Delegate: 0x2000e3f4 D: 45599 [IM]Received Read request D: 45603 [DMG]IM RH moving to [GeneratingReports] D: 45607 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 45616 [DMG] Cluster 3e, Attribute 3 is dirty D: 45621 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 45630 [DMG] Sending report (payload has 36 bytes)... I: 45636 [EM]<<< [E:24239r M:131709117] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 45646 [IN](S) Sending msg 131709117 on secure session with LSID: 22669 D: 45652 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 45660 [DMG] OnReportConfirm: NumReports = 0 D: 45664 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 45671 [DMG]IM RH moving to [AwaitingDestruction] D: 45676 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 45717 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45725 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 45733 [EM]>>> [E:24240r M:42699347] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) D: 45743 [EM]Handling via exchange: 24240r, Delegate: 0x2000e3f4 D: 45749 [DMG]Got Timed Request with timeout 10000: handler 0x2000e7f0 exchange 24240r I: 45757 [EM]<<< [E:24240r M:131709118] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 45767 [IN](S) Sending msg 131709118 on secure session with LSID: 22669 D: 45774 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43) D: 45782 [DMG]Timed Request time limit 0x000000000000D9E6: handler 0x2000e7f0 exchange 24240r D: 45837 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45845 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 45853 [EM]>>> [E:24240r M:42699348] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 45864 [EM]Found matching exchange: 24240r, Delegate: 0x2000e7f0 D: 45870 [DMG]Timed following action arrived at 0x000000000000B32E: handler 0x2000e7f0 exchange 24240r D: 45879 [DMG]Handing timed invoke to IM engine: handler 0x2000e7f0 exchange 24240r D: 45887 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 I: 45894 [FS]GeneralCommissioning: Received ArmFailSafe (900s) D: 45900 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 76c00f3e D: 45907 [DMG]Command handler moving to [ Preparing] D: 45911 [DMG]Command handler moving to [AddingComm] D: 45916 [DMG]Command handler moving to [AddedComma] D: 45921 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 45928 [EM]<<< [E:24240r M:131709119] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 45939 [IN](S) Sending msg 131709119 on secure session with LSID: 22669 D: 45945 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 45953 [DMG]Command handler moving to [CommandSen] D: 45958 [DMG]Command handler moving to [AwaitingDe] E: 45962 [DL]Long dispatch time: 117 ms, for event type 16388 D: 45987 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 45995 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 46003 [EM]>>> [E:24241r M:42699349] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 46014 [EM]Handling via exchange: 24241r, Delegate: 0x2000e3f4 D: 46020 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 46028 [ZCL]OpCreds: Certificate Chain request received for PAI D: 46034 [DMG]Command handler moving to [ Preparing] D: 46038 [DMG]Command handler moving to [AddingComm] D: 46043 [DMG]Command handler moving to [AddedComma] D: 46048 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 46057 [EM]<<< [E:24241r M:131709120] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 46068 [IN](S) Sending msg 131709120 on secure session with LSID: 22669 D: 46075 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 46082 [DMG]Command handler moving to [CommandSen] D: 46087 [DMG]Command handler moving to [AwaitingDe] D: 46257 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 46264 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 46437 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 46445 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48) D: 46497 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 46505 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 46513 [EM]>>> [E:24242r M:42699350] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 46524 [EM]Handling via exchange: 24242r, Delegate: 0x2000e3f4 D: 46530 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 46538 [ZCL]OpCreds: Certificate Chain request received for DAC D: 46544 [DMG]Command handler moving to [ Preparing] D: 46548 [DMG]Command handler moving to [AddingComm] D: 46553 [DMG]Command handler moving to [AddedComma] D: 46558 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 46567 [EM]<<< [E:24242r M:131709121] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 46578 [IN](S) Sending msg 131709121 on secure session with LSID: 22669 D: 46585 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 46592 [DMG]Command handler moving to [CommandSen] D: 46597 [DMG]Command handler moving to [AwaitingDe] D: 46767 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 46774 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 46947 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 46955 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 76) D: 47037 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 49257 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 51764 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 51822 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 54342 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 54659 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 54667 [EM]>>> [E:24243r M:42699351] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 54678 [EM]Handling via exchange: 24243r, Delegate: 0x2000e3f4 D: 54684 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 I: 54691 [ZCL]OpCreds: Received a CSRRequest command D: 54696 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0 I: 54859 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 54894 [ZCL]OpCreds: CSRRequest successful. D: 54898 [DMG]Command handler moving to [ Preparing] D: 54903 [DMG]Command handler moving to [AddingComm] D: 54907 [DMG]Command handler moving to [AddedComma] D: 54912 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 54921 [EM]<<< [E:24243r M:131709122] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 54931 [IN](S) Sending msg 131709122 on secure session with LSID: 22669 D: 54938 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) D: 54946 [DMG]Command handler moving to [CommandSen] D: 54950 [DMG]Command handler moving to [AwaitingDe] E: 54955 [DL]Long dispatch time: 296 ms, for event type 16388 D: 55197 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 55205 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 137) D: 55332 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 57672 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 59432 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 59519 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 59528 [EM]>>> [E:24244r M:42699352] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 59539 [EM]Handling via exchange: 24244r, Delegate: 0x2000e3f4 D: 59545 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B I: 59552 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 59613 [ZCL]OpCreds: AddTrustedRootCertificate successful. D: 59618 [DMG]Command handler moving to [ Preparing] D: 59623 [DMG]Command handler moving to [AddingComm] D: 59627 [DMG]Command handler moving to [AddedComma] D: 59632 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 59639 [EM]<<< [E:24244r M:131709123] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 59650 [IN](S) Sending msg 131709123 on secure session with LSID: 22669 D: 59657 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68) D: 59664 [DMG]Command handler moving to [CommandSen] D: 59669 [DMG]Command handler moving to [AwaitingDe] E: 59674 [DL]Long dispatch time: 155 ms, for event type 16388 D: 59742 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 59788 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 59882 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 59970 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 59981 [EM]>>> [E:24245r M:42699353] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 59992 [EM]Handling via exchange: 24245r, Delegate: 0x2000e3f4 D: 59998 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 I: 60006 [ZCL]OpCreds: Received an AddNOC command I: 60012 [FP]Validating NOC chain I: 60124 [FP]NOC chain validation successful I: 60128 [FP]Added new fabric at index: 0x1 I: 60132 [FP]Assigned compressed fabric ID: 0xFF6032CBA3F0E84E, node ID: 0x95314A8FC4458645 I: 60140 [TS]Last Known Good Time: 2023-02-09T11:08:43 I: 60145 [TS]New proposed Last Known Good Time: 2023-02-09T07:23:25 I: 60151 [TS]Retaining current Last Known Good Time D: 60155 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a2f8981a D: 60162 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a2f8981b D: 60177 [EVL]LogEvent event number: 0x0000000000010002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x000000000000EB10 I: 60191 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00000001 D: 60199 [DL]Using Thread extended MAC for hostname. I: 60204 [DIS]Advertise operational node FF6032CBA3F0E84E-95314A8FC4458645 D: 60211 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a2f8981c D: 60217 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a2f8981d D: 60223 [DMG]Command handler moving to [ Preparing] D: 60228 [DMG]Command handler moving to [AddingComm] D: 60233 [DMG]Command handler moving to [AddedComma] I: 60237 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC D: 60244 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 60251 [EM]<<< [E:24245r M:131709124] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:09 (IM:InvokeCommandResponse) I: 60262 [IN](S) Sending msg 131709124 on secure session with LSID: 22669 D: 60268 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 60276 [DMG]Command handler moving to [CommandSen] D: 60281 [DMG]Command handler moving to [AwaitingDe] E: 60286 [DL]Long dispatch time: 315 ms, for event type 16388 D: 60327 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 60335 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 60343 [EM]>>> [E:24246r M:42699354] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:02 (IM:ReadRequest) D: 60353 [EM]Handling via exchange: 24246r, Delegate: 0x2000e3f4 D: 60359 [IM]Received Read request D: 60363 [DMG]IM RH moving to [GeneratingReports] D: 60367 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 60376 [DMG] Cluster 31, Attribute fffc is dirty D: 60381 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0) D: 60390 [DMG] Sending report (payload has 37 bytes)... I: 60396 [EM]<<< [E:24246r M:131709125] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:05 (IM:ReportData) I: 60406 [IN](S) Sending msg 131709125 on secure session with LSID: 22669 D: 60412 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72) D: 60420 [DMG] OnReportConfirm: NumReports = 0 D: 60425 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 60432 [DMG]IM RH moving to [AwaitingDestruction] D: 60436 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 60507 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 61993 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 62000 [EM]>>> [E:24247r M:42699355] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:0a (IM:TimedRequest) D: 62011 [EM]Handling via exchange: 24247r, Delegate: 0x2000e3f4 D: 62016 [DMG]Got Timed Request with timeout 15000: handler 0x2000e7f0 exchange 24247r I: 62025 [EM]<<< [E:24247r M:131709126] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:01 (IM:StatusResponse) I: 62035 [IN](S) Sending msg 131709126 on secure session with LSID: 22669 D: 62041 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43) D: 62049 [DMG]Timed Request time limit 0x0000000000012CF9: handler 0x2000e7f0 exchange 24247r D: 62127 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 62173 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 62181 [EM]>>> [E:24247r M:42699356] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:08 (IM:InvokeCommandRequest) D: 62191 [EM]Found matching exchange: 24247r, Delegate: 0x2000e7f0 D: 62197 [DMG]Timed following action arrived at 0x000000000000F2F5: handler 0x2000e7f0 exchange 24247r D: 62207 [DMG]Handing timed invoke to IM engine: handler 0x2000e7f0 exchange 24247r D: 62214 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0000 D: 62225 [DMG]Decreasing reference count for CommandHandler, remaining 1 D: 62233 [DL]OpenThread State Changed (Flags: 0x01009009) D: 62238 [DL] Network Name: OpenThread D: 62242 [DL] PAN Id: 0xE094 D: 62244 [DL] Extended PAN Id: 0xDEAD00BEEF00CAFE D: 62249 [DL] Channel: 11 D: 62251 [DL] Mesh Prefix: fdde:ad00:beef::/64 D: 62256 [DL] Thread Unicast Addresses: D: 62260 [DL] fe80::c82a:552b:c050:f12e/64 valid preferred D: 64680 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 64737 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) I: 65140 [DL]Thread Network: ST-3011016721 Panid 0xcebb Channel 20 RSSI -30 LQI 255 Version 4 D: 67105 [DL]OpenThread State Changed (Flags: 0x00008000) D: 67110 [DL] Network Name: OpenThread D: 67114 [DL] PAN Id: 0xFFFF D: 67117 [DL] Extended PAN Id: 0xDEAD00BEEF00CAFE D: 67121 [DL] Channel: 11 D: 67124 [DL] Mesh Prefix: fdde:ad00:beef::/64 D: 67129 [DMG]Command handler moving to [ Preparing] D: 67134 [DMG]Command handler moving to [AddingComm] D: 67139 [DMG]Command handler moving to [AddedComma] D: 67143 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 76c00f3f D: 67150 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 67157 [EM]<<< [E:24247r M:131709127] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:09 (IM:InvokeCommandResponse) I: 67168 [IN](S) Sending msg 131709127 on secure session with LSID: 22669 D: 67175 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 125) D: 67182 [DMG]Command handler moving to [CommandSen] D: 67187 [DMG]Command handler moving to [AwaitingDe] D: 67192 [DL]OpenThread State Changed (Flags: 0x01002002) D: 67197 [DL] Thread Unicast Addresses: D: 67257 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 67302 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 67348 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 67355 [EM]>>> [E:24248r M:42699357] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:0a (IM:TimedRequest) D: 67366 [EM]Handling via exchange: 24248r, Delegate: 0x2000e3f4 D: 67371 [DMG]Got Timed Request with timeout 10000: handler 0x2000e7f0 exchange 24248r I: 67380 [EM]<<< [E:24248r M:131709128] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:01 (IM:StatusResponse) I: 67390 [IN](S) Sending msg 131709128 on secure session with LSID: 22669 D: 67396 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43) D: 67404 [DMG]Timed Request time limit 0x0000000000012E5C: handler 0x2000e7f0 exchange 24248r D: 67482 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 67491 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 67499 [EM]>>> [E:24248r M:42699358] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:08 (IM:InvokeCommandRequest) D: 67510 [EM]Found matching exchange: 24248r, Delegate: 0x2000e7f0 D: 67516 [DMG]Timed following action arrived at 0x00000000000107BC: handler 0x2000e7f0 exchange 24248r D: 67525 [DMG]Handing timed invoke to IM engine: handler 0x2000e7f0 exchange 24248r D: 67532 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003 D: 67541 [DMG]Command handler moving to [ Preparing] D: 67546 [DMG]Command handler moving to [AddingComm] D: 67551 [DMG]Command handler moving to [AddedComma] D: 67555 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 76c00f40 D: 67562 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 67569 [EM]<<< [E:24248r M:131709129] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:09 (IM:InvokeCommandResponse) I: 67580 [IN](S) Sending msg 131709129 on secure session with LSID: 22669 D: 67587 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 67594 [DMG]Command handler moving to [CommandSen] D: 67599 [DMG]Command handler moving to [AwaitingDe] E: 67604 [DL]Long dispatch time: 113 ms, for event type 16388 D: 67662 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 67670 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 67678 [EM]>>> [E:24249r M:42699359] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:0a (IM:TimedRequest) D: 67688 [EM]Handling via exchange: 24249r, Delegate: 0x2000e3f4 D: 67694 [DMG]Got Timed Request with timeout 10000: handler 0x2000e7f0 exchange 24249r I: 67702 [EM]<<< [E:24249r M:131709130] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:01 (IM:StatusResponse) I: 67713 [IN](S) Sending msg 131709130 on secure session with LSID: 22669 D: 67719 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43) D: 67727 [DMG]Timed Request time limit 0x0000000000012F9F: handler 0x2000e7f0 exchange 24249r D: 67842 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 67889 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 67897 [EM]>>> [E:24249r M:42699360] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:08 (IM:InvokeCommandRequest) D: 67908 [EM]Found matching exchange: 24249r, Delegate: 0x2000e7f0 D: 67914 [DMG]Timed following action arrived at 0x000000000001094A: handler 0x2000e7f0 exchange 24249r D: 67923 [DMG]Handing timed invoke to IM engine: handler 0x2000e7f0 exchange 24249r D: 67930 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006 D: 67946 [DMG]Decreasing reference count for CommandHandler, remaining 1 D: 67953 [DL]OpenThread State Changed (Flags: 0x1006c100) D: 67958 [DL] Network Name: OpenThread D: 67961 [DL] PAN Id: 0xCEBB D: 67964 [DL] Extended PAN Id: 0x9455CF8938B5C5F0 D: 67969 [DL] Channel: 20 D: 67971 [DL] Mesh Prefix: fdde:ad00:beef::/64 D: 67976 [DL]OpenThread State Changed (Flags: 0x1100101d) D: 67981 [DL] Device Role: DETACHED D: 67985 [DL] Thread Unicast Addresses: D: 67988 [DL] fdde:ad00:beef:0:ad8f:b8b1:b1c0:6616/64 valid D: 67994 [DL] fe80::c82a:552b:c050:f12e/64 valid preferred E: No response within timeout 500 ASSERTION FAIL [0] @ WEST_TOPDIR/zephyr/drivers/ieee802154/ieee802154_nrf5.c:1152 802.15.4 serialization error: -5 E: r0/a1: 0x00000004 r1/a2: 0x00000480 r2/a3: 0x200087d0 E: r3/a4: 0x20014584 r12/ip: 0x00000000 r14/lr: 0x0002c06f E: xpsr: 0x61100000 E: s[ 0]: 0x00000000 s[ 1]: 0x00000000 s[ 2]: 0x00000000 s[ 3]: 0x00000000 E: s[ 4]: 0x00000000 s[ 5]: 0x00000000 s[ 6]: 0x00000000 s[ 7]: 0x00000000 E: s[ 8]: 0x00000000 s[ 9]: 0x00000000 s[10]: 0x00000000 s[11]: 0x00000000 E: s[12]: 0x00000000 s[13]: 0x00000000 s[14]: 0x00000000 s[15]: 0x00000000 E: fpscr: 0x00000000 E: Faulting instruction address (r15/pc): 0x0007e398 E: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0 E: Current thread: 0x200087d0 (openthread) E: Halting system